[rrd-users] is rrd_update inconsistent with millisecond timestamps?

[Rick Jones]

I have a small utility that stores sFlow generic interface counter
samples into an RRD.  RRDis version 1.4.4.  That RRD is configured with
a step of 1 second and I am using the millisecond timestamp format in
the rrd_update() calls I am making.

The sFlow agent in this case seems to have a habit of occasionally
sending counter updates for a given interface at an interval rather less
than the configured 5 second sampling interval.  In fact, they can
occasionally arrive less than 12 milliseconds apart.  Naturally, I'll be
bringing that up with the source of this particular sFlow agent...

Here then the meat of the question. My utility is reporting that
rrd_update is upset about updates within the second.  It was my
understanding that when using the millisecond timestamp format that one
should be able to make multiple rrd_update calls per second.  That is
partially supported by the observation that rrd_update is not
consistently complaining here. That is, not every 12ish millisecond
interval elicits an rrd_update complaint.  Attached is a file with
snippets of tcpdump and syslog output showing both cases where
rrd_update() did not seem to complain, and cases where it did.  The
seqno being reported along with the rrd_update() error message is the
sFlow PDU sequence number visible in the tcpdump snippets.

Does this ring any bells with anyone?

Also, while I'm here, the char * returned by rrd_get_error() - does the
caller to rrd_get_error() need to free() that when finished with it?

thanks,

rick jones

BTW, while I have tcpdump timestamps, I do not have "stack
timestamps" (SO_TIMESTAMP) as returned in the recvmsg() calls I'm making
to get the PDUs out of the socket.  I am ass-u-me-ing the two are
"reasonably close" here.  Time time time, what has become of thee....

-------------- next part --------------
17:06:22.432990 IP (tos 0x0, ttl 253, id 27137, offset 0, flags [none], proto UDP (17), length 536)
    AGENT.2713 > COLLECTOR.6343: sFlowv5, IPv4 agent AGENT, agent-id 1, seqnum 367117, uptime 3557752668, samples 2, length 508
	expanded counter sample (4), length 172, seqnum 51345, type 0, idx 24, records 2
17:06:22.446188 IP (tos 0x0, ttl 253, id 27145, offset 0, flags [none], proto UDP (17), length 1316)
    AGENT.2713 > COLLECTOR.6343: sFlowv5, IPv4 agent AGENT, agent-id 1, seqnum 367121, uptime 3557752681, samples 7, length 1288
	expanded counter sample (4), length 172, seqnum 51346, type 0, idx 24, records 2
delta  0.013198

17:06:32.433078 IP (tos 0x0, ttl 253, id 27175, offset 0, flags [none], proto UDP (17), length 536)
    AGENT.2713 > COLLECTOR.6343: sFlowv5, IPv4 agent AGENT, agent-id 1, seqnum 367136, uptime 3557762668, samples 2, length 508
	expanded counter sample (4), length 172, seqnum 51348, type 0, idx 24, records 2
17:06:32.446349 IP (tos 0x0, ttl 253, id 27183, offset 0, flags [none], proto UDP (17), length 1316)
    AGENT.2713 > COLLECTOR.6343: sFlowv5, IPv4 agent AGENT, agent-id 1, seqnum 367140, uptime 3557762681, samples 7, length 1288
	expanded counter sample (4), length 172, seqnum 51349, type 0, idx 24, records 2
delta  0.013271


17:06:47.435146 IP (tos 0x0, ttl 253, id 27234, offset 0, flags [none], proto UDP (17), length 536)
    AGENT.2713 > COLLECTOR.6343: sFlowv5, IPv4 agent AGENT, agent-id 1, seqnum 367164, uptime 3557777670, samples 2, length 508  !
	expanded counter sample (4), length 172, seqnum 51352, type 0, idx 24, records 2
17:06:47.446186 IP (tos 0x0, ttl 253, id 27242, offset 0, flags [none], proto UDP (17), length 1316)
    AGENT.2713 > COLLECTOR.6343: sFlowv5, IPv4 agent AGENT, agent-id 1, seqnum 367168, uptime 3557777681, samples 7, length 1288 !
	expanded counter sample (4), length 172, seqnum 51353, type 0, idx 24, records 2
delta  0.011040
2011-05-20T17:06:47.528667-07:00 COLLECTOR /home/rjones/sfstored/sfstored[12875]: update_generic_counter_db() rrd_update() returned '/sflowdata/counters/AGENT/1/24/generic.rrd: illegal attempt to update using time 1305936407 when last update time is 1305936407 (minimum one second step)' PDU seqno 367168


17:06:52.432547 IP (tos 0x0, ttl 253, id 27252, offset 0, flags [none], proto UDP (17), length 536)
    AGENT.2713 > COLLECTOR.6343: sFlowv5, IPv4 agent AGENT, agent-id 1, seqnum 367173, uptime 3557782668, samples 2, length 508
	expanded flow sample (3), length 292, seqnum 9705, type 0, idx 24, rate 200000, pool 3061683443, drops 0, records 4
	expanded counter sample (4), length 172, seqnum 51354, type 0, idx 24, records 2
17:06:52.445833 IP (tos 0x0, ttl 253, id 27260, offset 0, flags [none], proto UDP (17), length 1316)
    AGENT.2713 > COLLECTOR.6343: sFlowv5, IPv4 agent AGENT, agent-id 1, seqnum 367177, uptime 3557782681, samples 7, length 1288
	expanded counter sample (4), length 172, seqnum 51355, type 0, idx 24, records 2
delta  0.013286

17:06:57.433645 IP (tos 0x0, ttl 253, id 27274, offset 0, flags [none], proto UDP (17), length 836)
    AGENT.2713 > COLLECTOR.6343: sFlowv5, IPv4 agent AGENT, agent-id 1, seqnum 367184, uptime 3557787669, samples 3, length 808  !
	expanded counter sample (4), length 172, seqnum 51356, type 0, idx 24, records 2
17:06:57.445417 IP (tos 0x0, ttl 253, id 27282, offset 0, flags [none], proto UDP (17), length 1316)
    AGENT.2713 > COLLECTOR.6343: sFlowv5, IPv4 agent AGENT, agent-id 1, seqnum 367188, uptime 3557787681, samples 7, length 1288 !
	expanded counter sample (4), length 172, seqnum 51357, type 0, idx 24, records 2
delta  0.011772
2011-05-20T17:06:57.532765-07:00 COLLECTOR /home/rjones/sfstored/sfstored[12875]: update_generic_counter_db() rrd_update() returned '/sflowdata/counters/AGENT/1/24/generic.rrd: illegal attempt to update using time 1305936417 when last update time is 1305936417 (minimum one second step)' PDU seqno 367188

17:07:07.433286 IP (tos 0x0, ttl 253, id 27310, offset 0, flags [none], proto UDP (17), length 536)
    AGENT.2713 > COLLECTOR.6343: sFlowv5, IPv4 agent AGENT, agent-id 1, seqnum 367202, uptime 3557797668, samples 2, length 508  !
	expanded flow sample (3), length 292, seqnum 9712, type 0, idx 24, rate 200000, pool 3062968597, drops 0, records 4
	expanded counter sample (4), length 172, seqnum 51359, type 0, idx 24, records 2
17:07:07.447266 IP (tos 0x0, ttl 253, id 27318, offset 0, flags [none], proto UDP (17), length 1316)
    AGENT.2713 > COLLECTOR.6343: sFlowv5, IPv4 agent AGENT, agent-id 1, seqnum 367206, uptime 3557797683, samples 7, length 1288 !
	expanded counter sample (4), length 172, seqnum 51360, type 0, idx 24, records 2
delta  0.013980
2011-05-20T17:07:07.506975-07:00 COLLECTOR /home/rjones/sfstored/sfstored[12875]: update_generic_counter_db() rrd_update() returned '/sflowdata/counters/AGENT/1/24/generic.rrd: illegal attempt to update using time 1305936427 when last update time is 1305936427 (minimum one second step)' PDU seqno 367206