From de785f04e11218cee7ff0d3e30fbcfc6da91ce87 Mon Sep 17 00:00:00 2001 From: Willy Tarreau Date: Thu, 22 Oct 2020 08:04:23 +0200 Subject: [PATCH] MINOR: threads/debug: only report lock stats for used operations In addition to the previous simplification, most locks don't use the seek or read lock (e.g. spinlocks etc) so let's split the dump into distinct operations (write/seek/read) and only report those which were used. Now the output size is roughly divided by 5 compared to previous ones. --- include/haproxy/thread.h | 66 ++++++++++++++++++++++------------------ 1 file changed, 37 insertions(+), 29 deletions(-) diff --git a/include/haproxy/thread.h b/include/haproxy/thread.h index 84571217c..e4d630ddf 100644 --- a/include/haproxy/thread.h +++ b/include/haproxy/thread.h @@ -464,36 +464,44 @@ static inline void show_lock_stats() } fprintf(stderr, - "Stats about Lock %s: \n" - "\t # write lock : %lu\n" - "\t # write unlock: %lu (%ld)\n" - "\t # wait time for write : %.3f msec\n" - "\t # wait time for write/lock: %.3f nsec\n" - "\t # seek lock : %lu\n" - "\t # seek unlock : %lu (%ld)\n" - "\t # wait time for seek : %.3f msec\n" - "\t # wait time for seek/lock : %.3f nsec\n" - "\t # read lock : %lu\n" - "\t # read unlock : %lu (%ld)\n" - "\t # wait time for read : %.3f msec\n" - "\t # wait time for read/lock : %.3f nsec\n", + "Stats about Lock %s: \n", + lock_label(lbl)); - lock_label(lbl), - lock_stats[lbl].num_write_locked, - lock_stats[lbl].num_write_unlocked, - lock_stats[lbl].num_write_unlocked - lock_stats[lbl].num_write_locked, - (double)lock_stats[lbl].nsec_wait_for_write / 1000000.0, - lock_stats[lbl].num_write_locked ? ((double)lock_stats[lbl].nsec_wait_for_write / (double)lock_stats[lbl].num_write_locked) : 0, - lock_stats[lbl].num_seek_locked, - lock_stats[lbl].num_seek_unlocked, - lock_stats[lbl].num_seek_unlocked - lock_stats[lbl].num_seek_locked, - (double)lock_stats[lbl].nsec_wait_for_seek / 1000000.0, - lock_stats[lbl].num_seek_locked ? ((double)lock_stats[lbl].nsec_wait_for_seek / (double)lock_stats[lbl].num_seek_locked) : 0, - lock_stats[lbl].num_read_locked, - lock_stats[lbl].num_read_unlocked, - lock_stats[lbl].num_read_unlocked - lock_stats[lbl].num_read_locked, - (double)lock_stats[lbl].nsec_wait_for_read / 1000000.0, - lock_stats[lbl].num_read_locked ? ((double)lock_stats[lbl].nsec_wait_for_read / (double)lock_stats[lbl].num_read_locked) : 0); + if (lock_stats[lbl].num_write_locked) + fprintf(stderr, + "\t # write lock : %lu\n" + "\t # write unlock: %lu (%ld)\n" + "\t # wait time for write : %.3f msec\n" + "\t # wait time for write/lock: %.3f nsec\n", + lock_stats[lbl].num_write_locked, + lock_stats[lbl].num_write_unlocked, + lock_stats[lbl].num_write_unlocked - lock_stats[lbl].num_write_locked, + (double)lock_stats[lbl].nsec_wait_for_write / 1000000.0, + lock_stats[lbl].num_write_locked ? ((double)lock_stats[lbl].nsec_wait_for_write / (double)lock_stats[lbl].num_write_locked) : 0); + + if (lock_stats[lbl].num_seek_locked) + fprintf(stderr, + "\t # seek lock : %lu\n" + "\t # seek unlock : %lu (%ld)\n" + "\t # wait time for seek : %.3f msec\n" + "\t # wait time for seek/lock : %.3f nsec\n", + lock_stats[lbl].num_seek_locked, + lock_stats[lbl].num_seek_unlocked, + lock_stats[lbl].num_seek_unlocked - lock_stats[lbl].num_seek_locked, + (double)lock_stats[lbl].nsec_wait_for_seek / 1000000.0, + lock_stats[lbl].num_seek_locked ? ((double)lock_stats[lbl].nsec_wait_for_seek / (double)lock_stats[lbl].num_seek_locked) : 0); + + if (lock_stats[lbl].num_read_locked) + fprintf(stderr, + "\t # read lock : %lu\n" + "\t # read unlock : %lu (%ld)\n" + "\t # wait time for read : %.3f msec\n" + "\t # wait time for read/lock : %.3f nsec\n", + lock_stats[lbl].num_read_locked, + lock_stats[lbl].num_read_unlocked, + lock_stats[lbl].num_read_unlocked - lock_stats[lbl].num_read_locked, + (double)lock_stats[lbl].nsec_wait_for_read / 1000000.0, + lock_stats[lbl].num_read_locked ? ((double)lock_stats[lbl].nsec_wait_for_read / (double)lock_stats[lbl].num_read_locked) : 0); } }