| Lustre 1.8 Operations Manual |    
|
| C H A P T E R 24 |
|
Lustre Debugging |
This chapter describes tips and information to debug Lustre, and includes the following sections:
Lustre is a complex system that requires a rich debugging environment to help locate problems.
Each Lustre debug message has the tag of the subsystem it originated in, the message type, and the location in the source code. The subsystems and debug types used in Lustre are as follows:
mdc, mds, osc, ost, obdclass, obdfilter, llite, ptlrpc, portals, lnd, ldlm, lov
Lustre uses the CDEBUG and CERROR macros to print the debug or error messages. To print the message, the CDEBUG macro uses portals_debug_msg (portals/linux/oslib/debug.c). The message format is described below, along with an example.
Lustre debug messages are maintained in a buffer, with the maximum buffer size specified (in MBs) by the debug_mb parameter (/proc/sys/lnet/debug_mb). The buffer is circular, so debug messages are kept until the allocated buffer limit is reached, and then the first messages are overwritten.
A variety of diagnostic and analysis tools are available to debug issues with the Lustre software. Some of these are provided in Linux distributions, while others have been developed and are made available by the Lustre project.
The following in-kernel debug mechanisms are incorporated into the Lustre software:
The following tools are also provided with the Lustre software:
The tools described in this section are provided in the Linux kernel or are available at an external website.
Some general debugging tools provided as a part of the standard Linux distro are:
The following logging and data collection tools can be used to collect information for debugging Lustre kernel issues:
The tools described in this section may be useful for debugging Lustre in a development environment.
A virtual machine is often used to create an isolated development and test environment. Some commonly-used virtual machines are:
A variety of debuggers and analysis tools are available including:
The debug_daemon allows users to control the Lustre kernel debug daemon to dump the debug_kernel buffer to a user-specified file. This functionality uses a kernel thread on top of debug_kernel. debug_kernel, another sub-command of lctl, continues to work in parallel with debug_daemon command.
Debug_daemon is highly dependent on file system write speed. File system writes operation may not be fast enough to flush out all the debug_buffer if Lustre file system is under heavy system load and continue to CDEBUG to the debug_buffer. Debug_daemon put ’DEBUG MARKER: Trace buffer full’ into the debug_buffer to indicate debug_buffer is overlapping itself before debug_daemon flush data to a file.
Users can use lctl control to start or stop Lustre daemon from dumping the debug_buffer to a file. Users can also temporarily hold daemon from dumping the file. Use of the debug_daemon sub-command to lctl can provide the same function.
This section describes lctl daemon debug commands.
$ lctl debug_daemon start [{file} {megabytes}]
Initiates the debug_daemon to start dumping debug_buffer into a file. The file can be a system default file, as shown in /proc/sys/lnet/debug_path. After Lustre starts, the default path is /tmp/lustre-log-$HOSTNAME. Users can specify a new filename for debug_daemon to output debug_buffer. The new file name shows up in /proc/sys/lnet/debug_path. Megabytes is the limitation of the file size in MBs. The daemon wraps around and dumps data to the beginning of the file when the output file size is over the limit of the user-specified file size. To decode the dumped file to ASCII and order the log entries by time, run:
lctl debug_file {file} > {newfile}
The output is internally sorted by the lctl command using quicksort.
Completely shuts down the debug_daemon operation and flushes the file output. Otherwise, debug_daemon is shut down as part of Lustre file system shutdown process. Users can restart debug_daemon by using start command after each stop command issued.
This is an example using debug_daemon with the interactive mode of lctl to dump debug logs to a 10 MB file.
#~/utils/lctl
To start daemon to dump debug_buffer into a 40 MB /tmp/dump file.
lctl > debug_daemon start /trace/log 40
To completely shut down the daemon.
lctl > debug_daemon stop
To start another daemon with an unlimited file size.
lctl > debug_daemon start /tmp/unlimited
The text message *** End of debug_daemon trace log *** appears at the end of each output file.
The amount of information printed to the kernel debug logs can be controlled by masks in /proc/sys/lnet/subsystem_debug and /proc/sys/lnet/debug. The subsystem_debug mask controls subsystems (e.g., obdfilter, net, portals, OSC, etc.) and the debug mask controls debug types written to the log (e.g., info, error, trace, alloc, etc.).
To turn off Lustre debugging completely:
sysctl -w lnet.debug=0
To turn on full Lustre debugging:
sysctl -w lnet.debug=-1
To turn on logging of messages related to network communications:
sysctl -w lnet.debug=net
To turn on logging of messages related to network communications and existing debug flags:
sysctl -w lnet.debug=+net
To turn off network logging with changing existing flags:
sysctl -w lnet.debug=-net
The various options available to print to kernel debug logs are listed in lnet/include/libcfs/libcfs.h
Lustre’s source code includes debug messages which are very useful for troubleshooting. As described above, debug messages are subdivided into a number of subsystems and types. This subdivision allows messages to be filtered, so that only messages of interest to the user are displayed. The lctl tool is useful to enable this filtering and manipulate the logs to extract the useful information from it. Use lctl to obtain the necessary debug messages:
1. To obtain a list of all the types and subsystems:
lctl > debug_list <subs | types>
lctl > filter <subsystem name | debug type>
3. To show debug messages belonging to certain subsystem or type:
lctl > show <subsystem name | debug type>
debug_kernel pulls the data from the kernel logs, filters it appropriately, and displays or saves it as per the specified options
lctl > debug_kernel [output filename]
If the debugging is being done on User Mode Linux (UML), it might be useful to save the logs on the host machine so that they can be used at a later time.
4. If you already have a debug log saved to disk (likely from a crash), to filter a log on disk:
lctl > debug_file <input filename> [output filename]
During the debug session, you can add markers or breaks to the log for any reason:
lctl > mark [marker text]
The marker text defaults to the current date and time in the debug log (similar to the example shown below):
DEBUG MARKER: Tue Mar 5 16:06:44 EST 2002
5. To completely flush the kernel debug buffer:
lctl > clear
| Note - Debug messages displayed with lctl are also subject to the kernel debug masks; the filters are additive. |
Memory leaks can occur in a code where you allocate a memory, but forget to free it when it becomes non-essential. You can use the leak_finder.pl tool to find memory leaks. Before running this program, you must turn on the debugging to collect all malloc and free entries. Run:
sysctl -w lnet.debug=+malloc
Dump the log into a user-specified log file using lctl (as shown in The lctl Tool). Run the leak finder on the newly-created log dump:
perl leak_finder.pl <ascii-logname>
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 displays the following output to show the leaks found:
Leak:32bytes allocated at a23a8fc(service.c:ptlrpc_init_svc:144,debug file line 241)
To dump debug messages to the console, set the corresponding debug mask in the printk flag:
sysctl -w lnet.printk=-1
This slows down the system dramatically. It is also possible to selectively enable or disable this for particular flags using:
sysctl -w lnet.printk=+vfstrace sysctl -w lnet.printk=-vfstrace
Lustre has a specific debug type category for tracing lock traffic. Use:
lctl> filter all_types lctl> show dlmtrace lctl> debug_kernel [filename]
lctl > debug_kernel /tmp/lustre_logs/log_all
Debug log: 324 lines, 324 kept, 0 dropped.
lctl > filter trace
Disabling output of type "trace"
lctl > debug_kernel /tmp/lustre_logs/log_notrace
Debug log: 324 lines, 282 kept, 42 dropped.
lctl > show trace
Enabling output of type "trace"
lctl > filter portals
Disabling output from subsystem "portals"
lctl > debug_kernel /tmp/lustre_logs/log_noportals
Debug log: 324 lines, 258 kept, 66 dropped.
In the Lustre source code, the debug infrastructure provides a number of macros which aid in debugging or reporting serious errors. All of these macros depend on having the DEBUG_SUBSYSTEM variable set at the top of the file:
#define DEBUG_SUBSYSTEM S_PORTALS
The operating system makes strace (program trace utility) available. Use strace to trace program execution. The strace utility pauses programs made by a process and records the system call, arguments, and return values. This is a very useful tool, especially when you try to troubleshoot a failed system call.
To invoke strace on a program:
$ strace <program> <args>
Sometimes, a system call may fork child processes. In this situation, use the -f option of strace to trace the child processes:
$ strace -f <program> <args>
To redirect the strace output to a file (to review at a later time):
$ strace -o <filename> <program> <args>
Use the -ff option, along with -o, to save the trace output in filename.pid, where pid is the process ID of the process being traced. Use the -ttt option 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 UML, save the traces on the host machine. In this example, hostfs is mounted on /r:
$ strace -o /r/tmp/vi.strace
In Lustre, the inodes on the metadata server contain extended attributes (EAs) that store information about file striping. EAs contain a list of all object IDs and their locations (that is, the OST that stores them). The lfs tool can be used to obtain this information for a given file via the getstripe sub-command. Use a corresponding lfs setstripe command to specify striping attributes for 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. To obtain this information for the file /mnt/lustre/frog in Lustre file system, run:
$ lfs getstripe /mnt/lustre/frog $ OBDs: 0 : OSC_localhost_UUID 1: OSC_localhost_2_UUID 2: OSC_localhost_3_UUID obdix 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 file system. The debugfs tool can either be used to check status or modify information in the file system. In Lustre, all objects that belong to a file are stored in an underlying ldiskfs file system on the OST's. The file system uses the object IDs as the file names. Once the object IDs are known, use the debugfs tool to obtain the attributes of all objects from different OST's. A sample run for the /mnt/lustre/frog file used in the above example is shown here:
$ 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
To determine the Lustre UUID of an obdfilter disk (for example, if you mix up the cables on your OST devices or the SCSI bus numbering suddenly changes and the SCSI devices get new names), use debugfs to get the last_rcvd file.
Lustre provides a modified version of tcpdump which helps to decode the complete Lustre message packet. This tool has more support to read packets from clients to OSTs, than to decode packets between clients and MDSs. The tcpdump module is available from Lustre CVS at www.sourceforge.net
cvs co -d :ext:<username>@cvs.lustre.org:/cvsroot/lustre tcpdump
Each service always maintains request history, which is useful for first occurrence troubleshooting. Ptlrpc history works as follows:
1. Request_in_callback() adds the new request to the service's request history.
2. When a request buffer becomes idle, add it to the service's request buffer history list.
3. 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.
Number of request buffers currently in the history
Maximum number of request buffers to keep
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>
|
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 |
Lustre offers a very lightweight tracing facility called LWT. It prints fixed size requests into a buffer and is much faster than LDEBUG. The LWT tracking facility is very successful to debug difficult problems.
LWT trace-based records that are dumped contain:
An lctl command dumps the logs to files.
| Lustre 1.8 Operations Manual | 821-0035-12 |
|
Copyright © 2010, Oracle and/or its affiliates. All rights reserved.