Bug #4740
closedkstat(1M) prints wrong snaptime
100%
Description
Here's a D script I've been using to trace kstat_read() invocations in a target process:
#!/usr/sbin/dtrace -s /* * kstat.d: trace kstat_read() calls in the target process and dump details * about the kstat that was read. */ #pragma D option quiet pid$target::kstat_read:entry { self->z = args[1]; } pid$target::kstat_read:return /self->z && self->z->ks_instance == 0/ { printf("kstat_read: %s %s %s %4d %d\\n", self->z->ks_module, self->z->ks_name, self->z->ks_class, self->z->ks_instance, self->z->ks_snaptime); self->z = 0; }
On SmartOS 20140403T042219Z, I ran this and got this output:
[root@headnode (sf-1) /var/tmp]# ./kstat.d -c 'kstat -p cpu:0:vm:snaptime 1 5' cpu:0:vm:snaptime 551739.402301749 kstat_read: kstat_headers 0 551784731060874 kstat_read: cpu vm misc 0 551784741828852 cpu:0:vm:snaptime 551784.741828852 kstat_read: cpu vm misc 0 551785741981082 cpu:0:vm:snaptime 551785.741981082 kstat_read: cpu vm misc 0 551786741974916 cpu:0:vm:snaptime 551786.741974916 kstat_read: cpu vm misc 0 551787741982980 cpu:0:vm:snaptime 551787.741982980 kstat_read: cpu vm misc 0 551788741885671
Note that kstat(1M) prints out 5 snaptimes, and there are 5 kstat_read() calls for the "cpu" kstat, but the snaptimes don't match up. The first snaptime that "kstat" prints was never read by kstat_read(). After that, "kstat" always seems to print the previous kstat_read()'s snaptime with the next one's data.
I believe that's exactly what the code in ks_instances_read() does. For a given kstat_t in the chain, it allocates a new ks_instance_t, copies the "crtime", "snaptime", and "class" into it, appends it to the list of instances that it will print out later, reads the kstat_t, and then copies the named values stored in ks_data. I think it should be copying "snaptime" after the kstat_read().
Updated by David Höppner over 8 years ago
This bug was introduced by me. You plan to provide a patch in illumos-joyent or here? Thanks for the analysis.
Updated by David Pacheco over 8 years ago
No problem. I haven't put together a patch yet because I found this while debugging another issue that I'm still working on.
Updated by Robert Mustacchi over 6 years ago
- Category set to cmd - userland programs
- Assignee set to Robert Mustacchi
Updated by Electric Monk over 6 years ago
- Status changed from New to Closed
- % Done changed from 0 to 100
git commit 6a19b8666104dbf912da5a4fb193c9c2b29e21bb
commit 6a19b8666104dbf912da5a4fb193c9c2b29e21bb Author: Robert Mustacchi <rm@joyent.com> Date: 2016-03-26T03:27:58.000Z 4740 kstat(1M) prints wrong snaptime Reviewed by: Dave Pacheco <dap@joyent.com> Reviewed by: David Höppner <0xffea@gmail.com> Reviewed by: Toomas Soome <tsoome@me.com> Approved by: Richard Lowe <richlowe@richlowe.net>