Add dbgmsg kstat

[behlendorf]

Internally ZFS keeps a small log to facilitate debugging. By default
the log is disabled, to enable it set zfs_dbgmsg_enable=1. The contents
of the log can be accessed by reading the /proc/spl/kstat/zfs/dbgmsg file.
Writing 0 to this proc file clears the log.

$ echo 1 >/sys/module/zfs/parameters/zfs_dbgmsg_enable
$ echo 0 >/proc/spl/kstat/zfs/dbgmsg
$ zpool import tank
$ cat /proc/spl/kstat/zfs/dbgmsg
1 0 0x01 -1 0 2492357525542 2525836565501
timestamp message
1441141408 spa=tank async request task=1
1441141408 txg 70 open pool version 5000; software version 5000/5; ...
1441141409 spa=tank async request task=32
1441141409 txg 72 import pool version 5000; software version 5000/5; ...
1441141414 command: lt-zpool import tank

Signed-off-by: Brian Behlendorf [email protected]

[richardelling]

LGTM, thanks!

[behlendorf]

One thing I noticed right away while testing this is that dprintf() isn't setup to log to the zfs_dbgmsg log. It's probably worth updating __dprintf() so it does. It's also a bit odd having two debug log functions: zfs_dbgmsg() and dprintf(). @richardelling do you happen to know why there are two interfaces?

[dweeezil]

@behlendorf I noticed the same thing. I just started looking at this. The overall concept looks just fine to me, however.

[richardelling]

@behlendorf I'm not sure of the history, good question for Matt

[kernelOfTruth]

@richardelling wrong thread (issue) ? ;)

referencing: #3730

[behlendorf]

I've refreshed the patch to map the zfs_dbgmsg() function to __dprintf(). This way all dprintf() and zfs_dbgmsg() messages appear in the kstat file and the log is genuinely useful. I refrained from converting all the zfs_dbgmsg() call sites to dprintf() to minimize any future merge conflicts. However, after spending some time on this I don't see any compelling reason to preserve both interfaces. It only adds needless confusion and since dprintf() is by far more heavily used zfs_dbgmsg() should go.

[nedbass]

LGTM and worked well in testing

[behlendorf]

@nedbass thanks for the review and testing. I've merged this to master.

[gaurkuma]

@behlendorf

I have a question regarding the debug infrastructure. It is definitely good and much needed but are they any plans on further improving it. Following are the issues i see with the current infra:

1. There is no log level support. I think it is very much needed. Even today most of the log messages seen are the txg moving through different states.
2. In a multi-pool environment, there is no way to tell from which pool the messages cropped up. We can add pool name as an arg or make this log pool specific by placing it under the pool directory. If there are logs which are common to all pools e.g. arc they can be maintained under /kstat/zfs
3. Wherein, i understand most of the places we rely on error counters, it may still be beneficial to log when we land up in error scenarios.
4. Use of dprintfs is very limited today and dtrace doesnt seem to work unless we change the Licence type from CDDL to GPL. We need more logs based on verbosity to debug intricate issues.
5. No Rate Limiting - An error message for e.g. unable to allocate a buffer from ARC when the dirty data in ARC reaches 50%, can easily fill up the log.

We are thinking of having logs based on the layers like DMU, ARC, ZIO, SPA, ZPL that can be enabled based on an exposed parameter (probably reuse zfs_flags for this purpose). We would like to know your thoughts since we do not want to deviate too much that merging with later releases becomes a problem for us. On the other hand, this may not be a bad time to rework debug infra since the no. of logs are quite limited.