Lustre Debugging for Developers

Intro...

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.

To use these macros, you will need to set the DEBUG_SUBSYSTEM variable at the top of the file to indicate what code module the debugging is part of as shown below:


 * 1) define DEBUG_SUBSYSTEM S_PORTALS

The available macros include:
 * LBUG - This is a panic style assertion in the kernel which causes Lustre to dump its circular log to the file /tmp/lustre-log from where it can be retrieved after a reboot.
 * LASSERT - Validates that a given expression is true, otherwise call LBUG. The failed expression is displayed on 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

What is this? CDEBUG(D_INFO, "This is my debug message: the number is %d\n", number);
 * CDEBUG - The basic and most commonly used debug macro, it takes one more argument than a standard printf - the debug type. OK to replace bold text with this? CDEBUG takes the standard printf arguments along with one additional argurment, the debug type. When the debug mask is set accordingly OK to change to this? to the corresponding debug type, this message is added to the debug log. Later, when the log is retrieved, it can also be filtered based on debug type.

What is this? CERROR("Something very bad has happened, and the return code is %d.\n", rc);
 * 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:


 * 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 information about the given ptlrpc_request structure.


 * OBD_FAIL_CHECK - 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.

Ptlrpc Request History
Each service maintains a request history, which can be useful for first occurrence troubleshooting.

Is ptlrpc an acronym?

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 the contents of the request buffer? 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.

The request history is accessed and controlled using the following /proc files under the service directory:

Note that requests in the history include "live" requests that are actually being handled. Each line in req_history looks like:



Where:

LWT Tracing
A lightweight tracing facility called LWT prints fixed size requests into a buffer and is faster than LDEBUG.

The records that are dumped contain:


 * Current CPU
 * Process counter
 * Pointer to file
 * Pointer to line in the file
 * Four void * pointers

An lctl command dumps the logs to files.

This tracking facility has been used successfully to debug difficult problems.

Is this included with Lustre?

=Finding memory leaks=

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. To use this program, follow these steps:

1. Turn on debugging to make sure all malloc and free entries are collected by entering:

sysctl -w lnet.debug=+malloc

2. Use lctl to dump the log into a user specified log file as shown in previous section.

3. Run the leak finder on the contents of the log file by entering:

perl leak_finder.pl 

The output is similar to:




 * 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 leak_finder.pl tool also displays any leaks that were found found:

Leak:32bytes allocated at a23a8fc (service.c:ptlrpc_init_svc:144,debug file line 241)