|
|
| (44 intermediate revisions by 2 users not shown) |
| Line 1: |
Line 1: |
| | <small>''(Updated: Jan 2011)''</small> |
| | __TOC__ |
| | The procedures below may be useful to developers debugging Lustre code. |
| | |
| == Adding Debugging to the Source Code == | | == Adding Debugging to the Source Code == |
| The debug infrastructure provides a number of macros which can be used in the Lustre source to aid debugging or report serious errors. All of these macros depend on having the ''DEBUG_SUBSYSTEM'' variable set at the top of the file to indicate what code module the debugging is part of: | | The debug infrastructure provides a number of macros that can be used in Lustre™ source code to aid in debugging or reporting serious errors. |
| | |
| : #define DEBUG_SUBSYSTEM S_PORTALS
| |
| * LBUG: This is a panic style assertion in the kernel which will cause Lustre to dump its circular log to the file ''/tmp/lustre-log'' from where it can be retrieved after a reboot.
| |
| * LASSERT: Validate that a given expression is true, otherwise call LBUG. The failed ''expression'' is printed onto the console, though the values that make up the expression are not printed.
| |
| * LASSERTF: Similar to '''LASSERT''' but also allows a free-format message to be printed, like printf/printk
| |
| * CDEBUG: CDEBUG is the basic and most commonly used debug macro, and takes just one more argument than a standard printf - the debug type. When the debug mask is set accordingly, this message will be added to the debug log. Later, when a troubleshooter retrieves that log, they can also filter based on this type.
| |
| : CDEBUG(D_INFO, "This is my debug message: the number is %d\n", number);
| |
| * CERROR: CERROR behaves similarly to CDEBUG, but prints the message in the debug log and to the console. This is appropriate for serious errors or fatal conditions:
| |
| : CERROR("Something very bad has happened, and the return code is %d.\n", rc);
| |
| * ENTRY and EXIT: ENTRY and EXIT take no arguments and simply add messages to aid in call tracing. One should attempt to cover all exit conditions when using these macros, to avoid confusion when the debug log reports that a function was entered but never exited.
| |
| * LDLM_DEBUG and LDLM_DEBUG_NOLOCK: These macros are to be used when tracing MDS and VFS operations for locking. The purpose of these macros is to build a thin trace that shows the protocol exchanges between nodes.
| |
| * DEBUG_REQ: prints a great deal of information about the given ptlrpc_request structure
| |
| | |
| * OBD_FAIL_CHECK: this allows insertion of failure points into the Lustre code, useful for generating regression tests that can hit a very specific sequence of events. This works in conjunction with "sysctl -w lustre.fail_loc={fail_loc}" to set a specific failure point for which a given OBD_FAIL_CHECK will test for.
| |
| * OBD_FAIL_TIMEOUT: like OBD_FAIL_CHECK, and if the given fail_loc is hit, wait for the specified number of seconds. Useful for simulating hung, blocked, or busy processes, or network delays
| |
| * OBD_RACE: like OBD_FAIL_CHECK, and the first process to hit it sleeps until a second process hits the same OBD_RACE and then both continue on. Useful for having multiple processes executing the same code concurrently to provoke locking races
| |
| * OBD_FAIL_ONCE: a flag set on a lustre.fail_loc breakpoint to cause the OBD_FAIL_CHECK condition to only be hit a single time. otherwise a fail_loc is permanent until cleared with "sysctl -w lustre.fail_loc=0"
| |
| * OBD_FAIL_RAND: have the OBD_FAIL_CHECK fail randomly, on average every (1 / lustre.fail_val) times
| |
| * OBD_FAIL_SKIP: have OBD_FAIL_CHECK succeed lustre.fail_val times, and then fail permanently, or once with OBD_FAIL_ONCE
| |
| * OBD_FAIL_SOME: have OBD_FAIL_CHECK fail lustre.fail_val times, and then succeed
| |
| | |
| == Debugging in User Mode Linux (UML) ==
| |
| The developers sometimes use gdb in UML to debug Lustre.
| |
| The Lustre startup puts the debug symbols for the newly-loaded modules into ''/tmp/gdb-{hostname}'' on the host machine.
| |
| These symbols can be loaded into gdb using the source command
| |
| in gdb via:
| |
| | |
| <pre>
| |
| symbol-file
| |
| delete
| |
| symbol-file /usr/src/lum/linux
| |
| source /tmp/gdb-{hostname}
| |
| b panic
| |
| b stop
| |
| </pre>
| |
| | |
| = Use of strace for Troubleshooting =
| |
| The '''strace''' is a system call trace utility made available by the operating system. It allows us to trace a system call, intercepts all the systems calls made by a process, and records the system call name, arguements, and return values. This is a very useful tool, especially when trying to troubleshoot a failed system call.
| |
| | |
| The '''strace''' can be invoked for a system call as shown below:
| |
| | |
| : $strace <system-call> <args>
| |
| A system call might sometimes fork child processes, we need to use the -f option of strace in such case to trace the child processes also:
| |
| | |
| : $strace -f <system-call> <args>
| |
| We can redirect the '''strace''' output to a file that maybe examined at a later time:
| |
| | |
| : $strace -o <filename> <system-call> <args>
| |
| We can use the -ff option along with -o to cause the trace output to be saved in ''filename.pid'', where ''pid'' is the process id of the process being traced.
| |
| Use "-ttt" to timestamp all lines in the strace output, so they can be correlated to operations in the lustre kernel debug log.
| |
| | |
| If the debugging is done in User mode Linux, it's a good idea to save the traces on the host machine by using the command shown below; here we assume that the hostfs is mounted on ''/r'':
| |
| | |
| : $strace -o /r/tmp/vi.strace
| |
| | |
| = Looking at Disk Content =
| |
| In Lustre, the information about objects that make a file is stored in the extended attributes of the file inode. This will contain a list of all the object ids and their locations (that is, which OST device stores them). Lustre has a tool called the '''lfs''' that can be used to obtain this information for a given file name via the '''getstripe''' subcommand. A corresponding '''lfs setstripe''' command can be used to specify the striping attributes of a new file or directory.
| |
| | |
| The '''lfs getstripe''' utility is written in C; it takes a Lustre filename as input and lists all the objects that form a part of this file. So, to obtain this information for the file ''/mnt/lustre/frog'' in Lustre filesystem, we would do:
| |
| | |
| {|
| |
| |-
| |
| |
| |
| $lfs getstripe /mnt/lustre/frog
| |
| $
| |
| OBDs:
| |
| 0 : OSC_localhost_UUID
| |
| 1 : OSC_localhost_2_UUID
| |
| 2 : OSC_localhost_3_UUID
| |
| obdidx objid
| |
| 0 17
| |
| 1 4
| |
| |}
| |
|
| |
|
| The ''' debugfs''' tool is provided by the e2fsprogs package; it can be used for interactive debugging of an ext3/ldiskfs filesystem. It can either be used just to check the status, or it can be used to modify some information in the filesystem, maybe to correct the filesystem state. In Lustre, all the objects that belong to a file are stored in an underlying ldiskfs filesystem on the OST's. The filesystem uses the object id's as the file names. So, once the object id's are known, '''debugfs''' can be used to obtain the attributes of all the objects from the different OST's. A sample run for the ''/mnt/lustre/frog'' file used in the example above is shown here:
| | To use these macros, you will need to set the ''DEBUG_SUBSYSTEM'' variable at the top of the file to as shown below: |
|
| |
|
| {|
| | #define DEBUG_SUBSYSTEM S_PORTALS |
| |-
| |
| |
| |
| $ debugfs -c /tmp/ost1
| |
| debugfs: cd O
| |
| debugfs: cd 0 /* for files in group 0 */
| |
| debugfs: cd d<objid % 32>
| |
| debugfs: stat <objid> /* for getattr on object */
| |
| debugfs: quit
| |
| ## Suppose object id is 36, then follow the steps below: | |
| $ debugfs /tmp/ost1
| |
| debugfs: cd O
| |
| debugfs: cd 0
| |
| debugfs: cd d4 /* objid % 32 */
| |
| debugfs: stat 36 /* for getattr on obj 4*/
| |
| debugfs: dump 36 /tmp/obj.36 /* dump contents of obj 4 */
| |
| debugfs: quit
| |
| |}
| |
| More help on '''debugfs''' can be obtained from the '''man pages'''.
| |
|
| |
|
| == Finding the lustre UUID of an OST ==
| | A list of available macros with descriptions is provided in see [http://wiki.lustre.org/manual/LustreManual20_HTML/LustreDebugging.html#50438274_pgfId-1296027 Section 28.3.1: ''Adding Debugging to the Lustre Source Code''] in the [http://wiki.lustre.org/manual/LustreManual20_HTML/index.html ''Lustre Operations Manual'']. |
| To find the Lustre UUID of an obdfilter disk (in the event, perhaps, you mix up the cables on your OST devices or the SCSI bus numbering suddenly changes and your SCSI devices get new names), use debugfs to get the last_rcvd file ''debugfs -R "dump last_rcvd /tmp/last_rcvf"''
| |
|
| |
|
| == Tcpdump == | | == Accessing a ''ptlrpc'' Request History == |
| Lustre provides a modified version of tcpdump that can be used to decode the complete Lustre message packet. '''[NOTE:''' It is currently
| | Each service maintains a request history, which can be useful for first occurrence troubleshooting. ''Prlrpc'' is an RPC protocol layered on LNET. This protocol deals with stateful servers and has semantics and built in support for recovery. ''Prlrpc'' is a subsystem in the Lustre Debug Messages section. |
| out-of-date and unusable] The tool has more developed support
| |
| to read packets from clients to OSTs; the functionality to decode the packets between clients and MDSs is not well developed yet.
| |
|
| |
|
| = Ptlrpc Request History =
| | For more information about how to use ''prlrpc'', see [http://wiki.lustre.org/manual/LustreManual20_HTML/LustreDebugging.html#50438274_pgfId-1296100 Section 28.3.2: ''Accessing a Ptlrpc Request History''] in the [http://wiki.lustre.org/manual/LustreManual20_HTML/index.html ''Lustre Operations Manual'']. |
| Each service always maintains request history, which is almost certainly very useful for first occurrence troubleshooting. The following email snippet describes the implementation.
| |
|
| |
|
| Ptlrpc history works as follows...
| | =Finding memory leaks using ''leak_finder.pl''= |
|
| |
|
| # request_in_callback() adds the new request to the service's request history.
| | Memory leaks can occur in code when memory has been allocated and then not freed once it is no longer required. The ''leak_finder.pl'' program provides a way to find memory leaks. |
| # When a request buffer becomes idle add it to the service's request buffer history list.
| |
| # Cull buffers from the service's request buffer history if it has grown above
| |
| "req_buffer_history_max" and remove its reqs from the service's request history.
| |
| Request history is accessed/controlled via the following /proc files under the service directory...
| |
|
| |
|
| * req_buffer_history_len # of request buffers currently in the history
| | For details, see [http://wiki.lustre.org/manual/LustreManual20_HTML/LustreDebugging.html#50438274_pgfId-1296154 Section 28.3.3: ''Finding Memory Leaks Using leak_finder.pl''] in the [http://wiki.lustre.org/manual/LustreManual20_HTML/index.html ''Lustre Operations Manual'']. |
| * req_buffer_history_max max # request buffers to keep
| |
| * req_history the request history
| |
| Note that requests in the history include "live" requests that are actually being handled. Each line in "req_history" looks like....
| |
|
| |
|
| <seq>:<target NID>:<client ID>:<xid>:<length>:<phase> <svc specific>
| | =Using LWT Tracing= |
| | | Lustre offers a lightweight tracing facility called LWT. It prints fixed size requests into a buffer and is much faster than LDEBUG. The LWT tracking facility can be used to debug difficult problems. Use of LWT tracing requires rebuilding LNET code. |
| * seq: request sequence number
| |
| * target NID: destination NID of the incoming request
| |
| * client ID: client's PID and NID
| |
| * xid: rq_xid
| |
| * length: size of the request message
| |
| * phase:
| |
| ** New (waiting to be handled or couldn't be unpacked)
| |
| ** Interpret (unpacked and being handled)
| |
| ** Complete (handled)
| |
| * svc specific:
| |
| ** Service-specific request printout. Currently the only service that does this is the OST, which prints the opcode if the message has been unpacked successfully.
| |
| | |
| = LWT Tracing = | |
| Also, Eric Barton has a very lightweight tracing facility called LWT. It prints fixed size requests into a buffer and is much faster than LDEBUG.
| |
| | |
| The records that are dumped contain: | |
|
| |
|
| | Dumped LWT trace-based records contain: |
| * Current CPU | | * Current CPU |
| * Process counter | | * Process counter |
| * Pointer to file | | * Pointer to file |
| * Pointer to line in the file | | * Pointer to line in the file |
| * 4 void * pointers | | * Four void * pointers |
| | |
| An '''lctl''' command dumps the logs to files.
| |
| | |
| This tracking facility has been very successful to debug difficult problems.
| |
| | |
| | |
| ----
| |
| | |
| ----
| |
| | |
| ----
| |
| | |
| | |
| | |
| | |
| | |
| | |
| [
| |
| | |
| [edit] LWT Tracing
| |
| | |
| Also, Eric Barton has a very lightweight tracing facility called LWT. It prints fixed size requests into a buffer and is much faster than LDEBUG.
| |
| | |
| The records that are dumped contain:
| |
| | |
| * Current CPU
| |
| * Process counter
| |
| * Pointer to file
| |
| * Pointer to line in the file
| |
| * 4 void * pointers
| |
| | |
| An lctl command dumps the logs to files.
| |
| | |
| This tracking facility has been very successful to debug difficult problems.
| |
| [edit] Finding memory leaks
| |
| | |
| Memory leaks can occur in a code where you allocate a memory, but forget to free it once its no longer required. Such problems can be found using the leak_finder.pl program. Before running this program, the debugging should be completely turned on to make sure all malloc and free entries are collected. This can be done as follows:
| |
| | |
| sysctl -w lnet.debug=+malloc
| |
| | |
| Dump the log into a user specified log file using lctl as shown in previous section. Run the leak finder after this on the just created log dump:
| |
| | |
| perl leak_finder.pl <ascii-logname>
| |
| | |
| This provides output as shown below:
| |
| | |
| malloced 8bytes at a3116744 called pathcopy
| |
| (lprocfs_status.c:lprocfs_add_vars:80)
| |
| freed 8bytes at a3116744 called pathcopy
| |
| (lprocfs_status.c:lprocfs_add_vars:80)
| |
| | |
| The tool will also give the following output to show the leaks found:
| |
|
| |
|
| Leak:32bytes allocated at a23a8fc (service.c:ptlrpc_init_svc:144,debug file line 241)
| | An ''lctl'' command can be used to dump the logs to files. |
