Project

General

Profile

Bug #4740

kstat(1M) prints wrong snaptime

Added by David Pacheco over 5 years ago. Updated over 3 years ago.

Status:
Closed
Priority:
Normal
Category:
cmd - userland programs
Start date:
2014-04-10
Due date:
% Done:

100%

Estimated time:
Difficulty:
Medium
Tags:
needs-triage

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().

History

#1

Updated by David Höppner over 5 years ago

This bug was introduced by me. You plan to provide a patch in illumos-joyent or here? Thanks for the analysis.

#2

Updated by David Pacheco over 5 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.

#3

Updated by Robert Mustacchi over 3 years ago

  • Category set to cmd - userland programs
  • Assignee set to Robert Mustacchi
#4

Updated by Electric Monk over 3 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>

Also available in: Atom PDF