[rrd-users] rrdgraph never returns with small step

[Josh Wyatt]

Josh Wyatt wrote:
> Alex van den Bogaerdt wrote:
>> I modified and combined your scripts.  I think it will do the
>> same as your originals.  See attached, please test.
>>
>> The last modification is that I put everyting in a for-each loop.
>> I didn't bother to count the different versions but there's quite
>> a few, as early as 1.2.9 upto 1.2.27 or so.
>>
>>
>> No hangs.
>>  
>>> Let me know if I can assist further.  Also FYI, I am running 1.3.0 
>>> currently.  Happy to try another version.
>> I think this may be wise.
> 
> Are you sure 1.2.27 resulted in no hangs for you?  I had tried 1.2.27 before (ebuild) and got hangs (but before I had this testsuite), and I just now downloaded 1.2.27 from oss.oetiker.ch and compiled it, and now I *do* get hangs.
> 
> And just like before with 1.2.27 I am seeing a memory leak, slowly consuming more and more memory.
> 

Okay, time to bring out a little firepower.
I ran strace on the testsuite (with -f to follow the child processes), and I see that at the point of the hang, rrdtool seems to go into an infinite loop opening /etc/localtime.

Here are the system calls leading up to that loop (on 1.3.0):
[pid 23691] open("tc1.rrd", O_RDONLY)   = 3
   1267 [pid 23691] fstat64(3, {st_mode=S_IFREG|0644, st_size=784, ...}) = 0
   1268 [pid 23691] fadvise64(3, 0, 0, POSIX_FADV_RANDOM) = 0
   1269 [pid 23691] mmap2(NULL, 784, PROT_READ, MAP_PRIVATE|MAP_NORESERVE, 3, 0) = 0xb7eab000
   1270 [pid 23691] madvise(0xb7eab000, 784, 0x1 /* MADV_??? */) = 0
   1271 [pid 23691] madvise(0xb7eab000, 112, MADV_SEQUENTIAL|0x1) = 0
   1272 [pid 23691] madvise(0xb7eab000, 120, MADV_SEQUENTIAL|0x1) = 0
   1273 [pid 23691] madvise(0xb7eab000, 108, MADV_SEQUENTIAL|0x1) = 0
   1274 [pid 23691] madvise(0xb7eab000, 8, MADV_SEQUENTIAL|0x1) = 0
   1275 [pid 23691] msync(0xb7eab000, 784, MS_ASYNC) = 0
   1276 [pid 23691] munmap(0xb7eab000, 784)     = 0
   1277 [pid 23691] close(3)                    = 0
   1278 [pid 23691] time(NULL)                  = 1213907966
   1279 [pid 23691] brk(0x80c8000)              = 0x80c8000
   1280 [pid 23691] brk(0x80ad000)              = 0x80ad000
   1281 [pid 23691] mmap2(NULL, 1077248, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb75d8000
   1282 [pid 23691] mmap2(NULL, 147456, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb75b4000
   1283 [pid 23691] munmap(0xb75b4000, 147456)  = 0
   1284 [pid 23691] mmap2(NULL, 270336, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7596000
   1285 [pid 23691] munmap(0xb7596000, 270336)  = 0
   1286 [pid 23691] mmap2(NULL, 270336, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7596000
   1287 [pid 23691] munmap(0xb7596000, 270336)  = 0
   1288 [pid 23691] open("/etc/localtime", O_RDONLY) = 3
   1289 [pid 23691] fstat64(3, {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
   1290 [pid 23691] close(3)                    = 0
   1291 [pid 23691] open("/etc/localtime", O_RDONLY) = 3
   1292 [pid 23691] fstat64(3, {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
   1293 [pid 23691] close(3)                    = 0
   1294 [pid 23691] open("/etc/localtime", O_RDONLY) = 3
   1295 [pid 23691] fstat64(3, {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
   1296 [pid 23691] close(3)                    = 0
   1297 [pid 23691] open("/etc/localtime", O_RDONLY) = 3
   1298 [pid 23691] fstat64(3, {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
   1299 [pid 23691] close(3)                    = 0


The hang on 1.2.27 was a little bit different, as apparently a font file got opened in the middle:
8813 [pid 23593] open("tc1.rrd", O_RDONLY)   = 3
   8814 [pid 23593] fadvise64(3, 0, 0, POSIX_FADV_RANDOM) = 0
   8815 [pid 23593] fstat64(3, {st_mode=S_IFREG|0644, st_size=784, ...}) = 0
   8816 [pid 23593] mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7ed8000
   8817 [pid 23593] read(3, "RRD\0000003\0\0\0\0/%\300\307C+\37[\1\0\0\0\1\0\0\0\1\0\0\0"..., 4096) = 784
   8818 [pid 23593] _llseek(3, -240, [544], SEEK_CUR) = 0
   8819 [pid 23593] _llseek(3, 0, [0], SEEK_SET) = 0
   8820 [pid 23593] read(3, "RRD\0000003\0\0\0\0/%\300\307C+\37[\1\0\0\0\1\0\0\0\1\0\0\0"..., 784) = 784
   8821 [pid 23593] _llseek(3, 784, [784], SEEK_SET) = 0
   8822 [pid 23593] close(3)                    = 0
   8823 [pid 23593] munmap(0xb7ed8000, 4096)    = 0
   8824 [pid 23593] time(NULL)                  = 1213907859
   8825 [pid 23593] open("/usr/local/rrdtool-1.2.27/share/rrdtool/fonts/DejaVuSansMono-Roman.ttf", O_RDONLY) = 3
   8826 [pid 23593] fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
   8827 [pid 23593] fstat64(3, {st_mode=S_IFREG|0644, st_size=60444, ...}) = 0
   8828 [pid 23593] mmap2(NULL, 60444, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7eca000
   8829 [pid 23593] close(3)                    = 0
   8830 [pid 23593] munmap(0xb7eca000, 60444)   = 0
   8831 [pid 23593] open("/etc/localtime", O_RDONLY) = 3
   8832 [pid 23593] fstat64(3, {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
   8833 [pid 23593] close(3)                    = 0
   8834 [pid 23593] open("/etc/localtime", O_RDONLY) = 3
   8835 [pid 23593] fstat64(3, {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
   8836 [pid 23593] close(3)                    = 0
   8837 [pid 23593] open("/etc/localtime", O_RDONLY) = 3
   8838 [pid 23593] fstat64(3, {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
   8839 [pid 23593] close(3)                    = 0
   8840 [pid 23593] open("/etc/localtime", O_RDONLY) = 3
   8841 [pid 23593] fstat64(3, {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
   8842 [pid 23593] close(3)                    = 0


Any additional thoughts on debugging this?  Beginning to look like something specific to my system, but not sure where to go next.
For kicks I checked out the disposition of /etc/localtime.  It's a symlink to a real zonefile:
root at monkeybiz testcase2 # file /etc/localtime
/etc/localtime: symbolic link to `/usr/share/zoneinfo/US/Eastern'
root at monkeybiz testcase2 # file /usr/share/zoneinfo/US/Eastern
/usr/share/zoneinfo/US/Eastern: timezone data


Thanks,
Josh