[rrd-users] rrdupdate time problem

[Oleg Derevenetz]

Alex van den Bogaerdt wrote:

>> I am developing NMS with ability to store variables (interface counters, temperature, environment, etc) in RRD. Due to heavy load 
>> (hundreds of thousands values stored in RRD per minute) I use some sort of buffering - counters from hardware with timestamps 
>> temporary stored in memory queues and periodically entire queue that relates to given RRD file stored into this file by separate 
>> thread using single command like that:
>>
>> ::Rrd::update file_path --template In:Out 1187065338:12345:6789 1187065358:123456:67890 ...
> 
> Sounds good.
> 
>> But sometimes such updates fails with error like that:
>>
>> RRD Error: illegal attempt to update using time 1187065338 when last update time is 1187065682 (minimum one second step)
>>
>> This error occures with different RRD files with different structures. I added debugging output regarding this problem, and this 
>> debug shows that before this error was no attempt to update this RRD file using timestamp 1187065682 at all, and failed command also 
>> does not contain argument with this timestamp.
> 
> I understand what you are saying, but I don't agree 100%.  What you have
> shown is that you believe there is no such update.  See below.
> 
>> How this can happen ? Any ideas ? I have only one idea - sometimes RRD file's last update time is time of real update, and not the 
>> latest timestamp from rrdupdate's data arguments, and if previous update happened later than the first counter value appears in 
>> memory queue, than such error will encounter on the next update.
> 
> This sounds reasonable however it would mean a bug in RRDtool, one which
> only manifests itself once in a while.
> 
> If you can reproduce the problem by replaying your logged updates,
> some bughunting is necessary.  But before this, I think it is fair
> to at least consider the possibility that you overlooked something.

I'll try to write a test tomorrow... This is an example (logged all 
updates to RRD files that contains string "cs3-anna-alstec" in file path):

Aug 14 03:03:25 mon TclMon: [ID 702911 local6.debug] thread [tid4bb]: 
RRD_SERVER: debug: ::Rrd::update 
/home/tclmon/var/objects_data/cs3-anna-alstec/INTERFACE/eth0/ifOctets.rrd 
--template In:Out 1187045853:36546:20357892

Aug 14 03:03:53 mon TclMon: [ID 702911 local6.debug] thread [tid4bb]: 
RRD_SERVER: debug: ::Rrd::update 
/home/tclmon/var/objects_data/cs3-anna-alstec/INTERFACE/eth0/ifHCPkts.rrd 
--template InUCast:InMCast:InBCast:OutUCast:OutMCast:OutBCast 
1187045853:562:0:0:334485:0:0

Aug 14 03:04:06 mon TclMon: [ID 702911 local6.debug] thread [tid4bb]: 
RRD_SERVER: debug: ::Rrd::update 
/home/tclmon/var/objects_data/cs3-anna-alstec/INTERFACE/eth0/ifUcastPkts.rrd 
--template In:Out 1187045853:562:334482

Aug 14 03:05:02 mon TclMon: [ID 702911 local6.debug] thread [tid4bb]: 
RRD_SERVER: debug: ::Rrd::update 
/home/tclmon/var/objects_data/cs3-anna-alstec/INTERFACE/eth0/ifErrors.rrd 
--template In:Out 1187045853:0:0

Aug 14 08:28:09 mon TclMon: [ID 702911 local6.debug] thread [tid4bb]: 
RRD_SERVER: debug: ::Rrd::update 
/home/tclmon/var/objects_data/cs3-anna-alstec/INTERFACE/hdlc13/ifHCOctets.rrd 
--template In:Out 1187065338:14850228:34819645

Aug 14 08:28:09 mon TclMon: [ID 702911 local6.error] thread [tid4bb]: 
RRD_SERVER: cannot update RRD database 
/home/tclmon/var/objects_data/cs3-anna-alstec/INTERFACE/hdlc13/ifHCOctets.rrd 
using command ::Rrd::update 
/home/tclmon/var/objects_data/cs3-anna-alstec/INTERFACE/hdlc13/ifHCOctets.rrd 
--template In:Out 1187065338:14850228:34819645: RRD Error: illegal 
attempt to update using time 1187065338 when last update time is 
1187065679 (minimum one second step)

Time in logs is local time in MSD timezone. Rrdupdate complains that 
there was update at 1187065679 (08:27 MSD) for file 
cs3-anna-alstec/INTERFACE/hdlc13/ifHCOctets.rrd, but there was no 
updates at all since 03:XX MSD because device was offline. I suppose 
that there may be some uninitialized variable or something like so 
previous call to rrdupdate for some other file may trigger this.

--
Oleg Derevenetz <oleg at vsi.ru> OOD3-RIPE
Phone: +7 4732 539880
Fax:   +7 4732 531415         http://www.vsi.ru
CenterTelecom Voronezh ISP    http://isp.vsi.ru