diff options
Diffstat (limited to 'doc/debugging/statedump.md')
| -rw-r--r-- | doc/debugging/statedump.md | 77 |
1 files changed, 43 insertions, 34 deletions
diff --git a/doc/debugging/statedump.md b/doc/debugging/statedump.md index 9939576e270..9d594320ddc 100644 --- a/doc/debugging/statedump.md +++ b/doc/debugging/statedump.md @@ -1,21 +1,30 @@ -#Statedump +# Statedump Statedump is a file generated by glusterfs process with different data structure state which may contain the active inodes, fds, mempools, iobufs, memory allocation stats of different types of datastructures per xlator etc. -##How to generate statedump -We can find the directory where statedump files are created using 'gluster --print-statedumpdir' command. +## How to generate statedump +We can find the directory where statedump files are created using `gluster --print-statedumpdir` command. Create that directory if not already present based on the type of installation. Lets call this directory `statedump-directory`. -We can generate statedump using 'kill -USR1 <pid-of-gluster-process>'. +We can generate statedump using `kill -USR1 <pid-of-gluster-process>`. gluster-process is nothing but glusterd/glusterfs/glusterfsd process. There are also commands to generate statedumps for brick processes/nfs server/quotad -For bricks: `gluster volume statedump <volname>` +For bricks: +``` +gluster volume statedump <volname> +``` -For nfs server: `gluster volume statedump <volname> nfs` +For nfs server: +``` +gluster volume statedump <volname> nfs +``` -For quotad: `gluster volume statedump <volname> quotad` +For quotad: +``` +gluster volume statedump <volname> quotad +``` For brick-processes files will be created in `statedump-directory` with name of the file as `hyphenated-brick-path.<pid>.dump.timestamp`. For all other processes it will be `glusterdump.<pid>.dump.timestamp`. @@ -24,21 +33,21 @@ processes could have used the `SIGUSR1` signal already for other purposes. To generate statedump for the processes, using libgfapi, below command can be executed from one of the nodes in the gluster cluster to which the libgfapi application is connected to. - - gluster volume statedump <volname> client <hostname>:<process id> - +``` +gluster volume statedump <volname> client <hostname>:<process id> +``` The statedumps can be found in the `statedump-directory`, the name of the statedumps being `glusterdump.<pid>.dump.timestamp`. For a process there can be multiple such files created depending on the number of times the volume is accessed by the process (related to the number of `glfs_init()` calls). -##How to read statedump +## How to read statedump We shall see snippets of each type of statedump. First and last lines of the file have starting and ending time of writing the statedump file. Times will be in UTC timezone. mallinfo return status is printed in the following format. Please read man mallinfo for more information about what each field means. -###Mallinfo +### Mallinfo ``` [mallinfo] mallinfo_arena=100020224 /* Non-mmapped space allocated (bytes) */ @@ -53,7 +62,7 @@ mallinfo_fordblks=3310112 /* Total free space (bytes) */ mallinfo_keepcost=133712 /* Top-most, releasable space (bytes) */ ``` -###Data structure allocation stats +### Data structure allocation stats For every xlator data structure memory per translator loaded in the call-graph is displayed in the following format: For xlator with name: glusterfs @@ -74,7 +83,7 @@ max_num_allocs=3 #Maximum number of active allocations at any point in the life total_allocs=7 #Number of times this data is allocated in the life of the process. ``` -###Mempools +### Mempools Mempools are optimization to reduce the number of allocations of a data type. If we create a mem-pool of lets say 1024 elements for a data-type, new elements will be allocated from heap using syscalls like calloc, only if all the 1024 elements in the pool are in active use. @@ -94,7 +103,7 @@ cur-stdalloc=0 #Denotes the number of allocations made from heap once cold-count max-stdalloc=0 #Maximum number of allocations from heap that are in active use at any point in the life of the process. ``` -###Iobufs +### Iobufs ``` [iobuf.global] iobuf_pool=0x1f0d970 #The memory pool for iobufs @@ -105,7 +114,7 @@ iobuf_pool.arena_cnt=8 #Total number of arenas in the pool iobuf_pool.request_misses=0 #The number of iobufs that were stdalloc'd (as they exceeded the default max page size provided by iobuf_pool). ``` -There are 3 lists of arenas +There are 3 lists of arenas: 1. Arena list: arenas allocated during iobuf pool creation and the arenas that are in use(active_cnt != 0) will be part of this list. 2. Purge list: arenas that can be purged(no active iobufs, active_cnt == 0). @@ -142,7 +151,7 @@ arena.6.active_iobuf.2.ptr=0x7fdb92189000 At any given point in time if there are lots of filled arenas then that could be a sign of iobuf leaks. -###Call stack +### Call stack All the fops received by gluster are handled using call-stacks. Call stack contains the information about uid/gid/pid etc of the process that is executing the fop. Each call-stack contains different call-frames per xlator which handles that fop. ``` @@ -157,7 +166,7 @@ op=LOOKUP #Fop type=1 #Type of the op i.e. FOP/MGMT-OP cnt=9 #Number of frames in this stack. ``` -###Call-frame +### Call-frame Each frame will have information about which xlator the frame belongs to, what is the function it wound to/from and will be unwind to. It also mentions if the unwind happened or not. If we observe hangs in the system and want to find out which xlator is causing it. Take a statedump and see what is the final xlator which is yet to be unwound. ``` @@ -172,7 +181,7 @@ wind_to=priv->children[i]->fops->lookup unwind_to=afr_lookup_cbk #Parent xlator function to which unwind happened ``` -###History of operations in Fuse +### History of operations in Fuse Fuse maintains history of operations that happened in fuse. @@ -188,7 +197,7 @@ TIME=2014-07-09 16:44:57.523394 message=[0] fuse_getattr_resume: 4591, STAT, path: (/iozone.tmp), gfid: (3afb4968-5100-478d-91e9-76264e634c9f) ``` -###Xlator configuration +### Xlator configuration ``` [cluster/replicate.r2-replicate-0] #Xlator type, name information child_count=2 #Number of children to the xlator @@ -208,7 +217,7 @@ favorite_child=-1 wait_count=1 ``` -###Graph/inode table +### Graph/inode table ``` [active graph - 1] @@ -220,7 +229,7 @@ conn.1.bound_xl./data/brick01a/homegfs.lru_size=183 #Number of inodes present in conn.1.bound_xl./data/brick01a/homegfs.purge_size=0 #Number of inodes present in purge list ``` -###Inode +### Inode ``` [conn.1.bound_xl./data/brick01a/homegfs.active.324] #324th inode in active inode list gfid=e6d337cf-97eb-44b3-9492-379ba3f6ad42 #Gfid of the inode @@ -239,7 +248,7 @@ ia_type=2 Ref by xl:.fuse=1 Ref by xl:.patchy-client-0=-1 ``` -###Inode context +### Inode context For each inode per xlator some context could be stored. This context can also be printed in the statedump. Here is the inode ctx of locks xlator ``` [xlator.features.locks.homegfs-locks.inode] @@ -256,12 +265,12 @@ lock-dump.domain.domain=homegfs-replicate-0 #Domain name where entry/data operat inodelk.inodelk[0](ACTIVE)=type=WRITE, whence=0, start=11141120, len=131072, pid = 18446744073709551615, owner=080b1ada117f0000, client=0xb7fc30, connection-id=compute-30-029.com-3505-2014/06/29-14:46:12:477358-homegfs-client-0-0-1, granted at Sun Jun 29 11:10:36 2014 #Active lock information ``` -##FAQ -###How to debug Memory leaks using statedump? +## FAQ +### How to debug Memory leaks using statedump? -####Using memory accounting feature: +#### Using memory accounting feature: -`https://bugzilla.redhat.com/show_bug.cgi?id=1120151` is one of the bugs which was debugged using statedump to see which data-structure is leaking. Here is the process used to find what the leak is using statedump. According to the bug the observation is that the process memory usage is increasing whenever one of the bricks is wiped in a replicate volume and a `full` self-heal is invoked to heal the contents. Statedump of the process is taken using kill -USR1 `<pid-of-gluster-self-heal-daemon>`. +[Bug 1120151](https://bugzilla.redhat.com/show_bug.cgi?id=1120151) is one of the bugs which was debugged using statedump to see which data-structure is leaking. Here is the process used to find what the leak is using statedump. According to the bug the observation is that the process memory usage is increasing whenever one of the bricks is wiped in a replicate volume and a `full` self-heal is invoked to heal the contents. Statedump of the process is taken using `kill -USR1 <pid-of-gluster-self-heal-daemon>`. ``` grep -w num_allocs glusterdump.5225.dump.1405493251 num_allocs=77078 @@ -284,10 +293,10 @@ grep of the statedump revealed too many allocations for the following data-types 3. gf_common_mt_mem_pool. After checking afr-code for allocations with tag `gf_common_mt_char` found `data-self-heal` code path does not free one such allocated memory. `gf_common_mt_mem_pool` suggests that there is a leak in pool memory. `replicate-0:dict_t`, `glusterfs:data_t` and `glusterfs:data_pair_t` pools are using lot of memory, i.e. cold_count is `0` and too many allocations. Checking source code of dict.c revealed that `key` in `dict` is allocated with `gf_common_mt_char` i.e. `2.` tag and value is created using gf_asprintf which in-turn uses `gf_common_mt_asprintf` i.e. `1.`. Browsing the code for leak in self-heal code paths lead to a line which over-writes a variable with new dictionary even when it was already holding a reference to another dictionary. After fixing these leaks, ran the same test to verify that none of the `num_allocs` are increasing even after healing 10,000 files directory hierarchy in statedump of self-heal daemon. -Please check http://review.gluster.org/8316 for more info about patch/code. +Please check this [patch](http://review.gluster.org/8316) for more info about the fix. -####Debugging leaks in memory pools: -Statedump output of memory pools was used to test and verify the fixes to https://bugzilla.redhat.com/show_bug.cgi?id=1134221. On code analysis, dict_t objects were found to be leaking (in terms of not being unref'd enough number of times, during name self-heal. The test involved creating 100 files on plain replicate volume, removing them from one of the bricks's backend, and then triggering lookup on them from the mount point. Statedump of the mount process was taken before executing the test case and after it, after compiling glusterfs with -DDEBUG flags (to have cold count set to 0 by default). +#### Debugging leaks in memory pools: +Statedump output of memory pools was used to test and verify the fixes to [Bug 1134221](https://bugzilla.redhat.com/show_bug.cgi?id=1134221). On code analysis, dict_t objects were found to be leaking (in terms of not being unref'd enough number of times, during name self-heal. The test involved creating 100 files on plain replicate volume, removing them from one of the brick's backend, and then triggering lookup on them from the mount point. Statedump of the mount process was taken before executing the test case and after it, after compiling glusterfs with -DDEBUG flags (to have cold count set to 0 by default). Statedump output of the fuse mount process before the test case was executed: @@ -319,7 +328,7 @@ cur-stdalloc=214 max-stdalloc=220 ``` -Here, with cold count being 0 by default, cur-stdalloc indicated the number of dict_t objects that were allocated in heap using mem_get(), and yet to be freed using mem_put() (refer to https://github.com/gluster/glusterfs/blob/master/doc/data-structures/mem-pool.md for more details on how mempool works). After the test case (name selfheal of 100 files), there was a rise in the cur-stdalloc value (from 14 to 214) for dict_t. +Here, with cold count being 0 by default, `cur-stdalloc` indicated the number of `dict_t` objects that were allocated in heap using `mem_get()`, and yet to be freed using `mem_put()` (refer to this [page](https://github.com/gluster/glusterfs/blob/master/doc/data-structures/mem-pool.md) for more details on how mempool works). After the test case (name selfheal of 100 files), there was a rise in the cur-stdalloc value (from 14 to 214) for `dict_t`. After these leaks were fixed, glusterfs was again compiled with -DDEBUG flags, and the same steps were performed again and statedump was taken before and after executing the test case, of the mount. This was done to ascertain the validity of the fix. And the following are the results: @@ -353,8 +362,8 @@ max-stdalloc=119 ``` The value of cur-stdalloc remained 14 before and after the test, indicating that the fix indeed does what it's supposed to do. -###How to debug hangs because of frame-loss? -`https://bugzilla.redhat.com/show_bug.cgi?id=994959` is one of the bugs where statedump was helpful in finding where the frame was lost. Here is the process used to find where the hang is using statedump. +### How to debug hangs because of frame-loss? +[Bug 994959](https://bugzilla.redhat.com/show_bug.cgi?id=994959) is one of the bugs where statedump was helpful in finding where the frame was lost. Here is the process used to find where the hang is using statedump. When the hang was observed, statedumps are taken for all the processes. On mount's statedump the following stack is shown: ``` [global.callpool.stack.1.frame.1] @@ -402,4 +411,4 @@ unwind_to=qr_readdirp_cbk ``` `unwind_to` shows that call was unwound to `afr_readdirp_cbk` from client xlator. Inspecting that function revealed that afr is not unwinding the stack when fop failed. -Check http://review.gluster.org/5531 for more info about patch/code changes. +Check this [patch](http://review.gluster.org/5531) for more info about the fix. |