WARNING: This is the _old_ Lustre wiki, and it is in the process of being retired. The information found here is all likely to be out of date. Please search the new wiki for more up to date information.

Difference between revisions of "Lustre Debugging for Developers"

From Obsolete Lustre Wiki
Jump to navigationJump to search
 
(37 intermediate revisions by 2 users not shown)
Line 1: Line 1:
[[Intro...]]
+
<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.  
+
The debug infrastructure provides a number of macros that can be used in Lustre™ source code to aid in debugging or reporting 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:
+
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
 
  #define DEBUG_SUBSYSTEM S_PORTALS
  
The available macros include:
+
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''].
* '''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]]
 
 
 
* '''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?]]
 
CDEBUG(D_INFO, "This is my debug message: the number is %d\n", number);
 
 
 
* '''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:
 
[[What is this?]]
 
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 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:
 
 
 
# request_in_callback() adds the new request to the service's request history.
 
# When a request buffer becomes idle add '''it''' [[the contents of the request buffer?]] 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      Number of request buffers currently in the history
+
== Accessing a ''ptlrpc'' Request History ==
: req_buffer_history_max      Maximum number of request buffers to keep
+
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.
: req_history                [[Request history]]
 
  
Note that requests in the history include "live" requests that are actually being handled. Each line in ''req_history'' looks like:
+
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''].
  
<seq>:<target NID>:<client ID>:<xid>:<length>:<phase> <svc specific>
+
=Finding memory leaks using ''leak_finder.pl''=
  
Where:
+
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.   
: 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 printoutCurrently the only service that does this is the OST, which prints the opcode if the message has been unpacked successfully.
 
  
= LWT Tracing =
+
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''].
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:
+
=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.
  
 +
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.
 
 
 
=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.

Latest revision as of 08:18, 20 January 2011

(Updated: Jan 2011)

The procedures below may be useful to developers debugging Lustre code.

Adding Debugging to the Source Code

The debug infrastructure provides a number of macros that can be used in Lustre™ source code to aid in debugging or reporting serious errors.

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

A list of available macros with descriptions is provided in see Section 28.3.1: Adding Debugging to the Lustre Source Code in the Lustre Operations Manual.

Accessing a ptlrpc Request History

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.

For more information about how to use prlrpc, see Section 28.3.2: Accessing a Ptlrpc Request History in the Lustre Operations Manual.

Finding memory leaks using leak_finder.pl

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.

For details, see Section 28.3.3: Finding Memory Leaks Using leak_finder.pl in the Lustre Operations Manual.

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.

Dumped LWT trace-based records contain:

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

An lctl command can be used to dump the logs to files.