Whamcloud - gitweb
FIX: added index.
[doc/manual.git] / LustreDebugging.xml
1 <?xml version='1.0' encoding='UTF-8'?>
2 <!-- This document was created with Syntext Serna Free. --><chapter xmlns="http://docbook.org/ns/docbook" xmlns:xl="http://www.w3.org/1999/xlink" version="5.0" xml:lang="en-US" xml:id="lustredebugging">
3   <title xml:id="lustredebugging.title">Lustre Debugging</title>
4   <para>This chapter describes tips and information to debug Lustre, and includes the following sections:</para>
5   <itemizedlist>
6     <listitem>
7       <para><xref linkend="dbdoclet.50438274_15874"/></para>
8     </listitem>
9     <listitem>
10       <para><xref linkend="dbdoclet.50438274_23607"/></para>
11     </listitem>
12     <listitem>
13       <para><xref linkend="dbdoclet.50438274_80443"/></para>
14     </listitem>
15   </itemizedlist>
16   <section xml:id="dbdoclet.50438274_15874">
17     <title><indexterm><primary>debugging</primary></indexterm>
18 Diagnostic and Debugging Tools</title>
19     <para>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.</para>
20     <section remap="h3">
21       <title><indexterm><primary>debugging</primary><secondary>tools</secondary></indexterm>
22 Lustre Debugging Tools</title>
23       <para>The following in-kernel debug mechanisms are incorporated into the Lustre software:</para>
24       <itemizedlist>
25         <listitem>
26           <para><emphasis role="bold">Debug logs</emphasis>  - A circular debug buffer to which Lustre internal debug messages are written (in contrast to error messages, which are printed to the syslog or console). Entries to the Lustre debug log are controlled by the mask set by <literal>/proc/sys/lnet/debug</literal>. The log size defaults to 5 MB per CPU but can be increased as a busy system will quickly overwrite 5 MB. When the buffer fills, the oldest information is discarded.</para>
27         </listitem>
28         <listitem>
29           <para><emphasis role="bold">Debug daemon</emphasis>  - The debug daemon controls logging of debug messages.</para>
30         </listitem>
31         <listitem>
32           <para><emphasis role="bold">
33               <literal>/proc/sys/lnet/debug</literal>
34             </emphasis>  - This file contains a mask that can be used to delimit the debugging information written out to the kernel debug logs.</para>
35         </listitem>
36       </itemizedlist>
37       <para>The following tools are also provided with the Lustre software:</para>
38       <itemizedlist>
39         <listitem>
40           <para><emphasis role="bold">
41               <literal>lctl</literal>
42             </emphasis>  - This tool is used with the debug_kernel option to manually dump the Lustre debugging log or post-process debugging logs that are dumped automatically. For more information about the lctl tool, see <xref linkend="dbdoclet.50438274_62472"/> and <xref linkend="dbdoclet.50438219_38274"/>.</para>
43         </listitem>
44         <listitem>
45           <para><replaceable role="bold">Lustre subsystem asserts</replaceable>  - A panic-style assertion (LBUG) in the kernel causes Lustre to dump the debug log to the file <literal>/tmp/lustre-log.<replaceable>&lt;timestamp&gt;</replaceable></literal> where it can be retrieved after a reboot. For more information, see <xref linkend="dbdoclet.50438198_40669"/>.</para>
46         </listitem>
47         <listitem>
48           <para>
49                   <literal>
50               <replaceable>lfs</replaceable>
51             </literal>
52                   - This utility provides access to the extended attributes (EAs) of a Lustre file (along with other information). For more inforamtion about lfs, see <xref linkend="dbdoclet.50438206_94597"/>.</para>
53         </listitem>
54       </itemizedlist>
55     </section>
56     <section remap="h3">
57       <title><indexterm><primary>debugging</primary><secondary>external tools</secondary></indexterm>External Debugging Tools</title>
58       <para>The tools described in this section are provided in the Linux kernel or are available at an external website. For information about using some of these tools for Lustre debugging, see <xref linkend="dbdoclet.50438274_23607"/> and <xref linkend="dbdoclet.50438274_80443"/>.</para>
59       <section remap="h4">
60         <title><indexterm><primary>debugging</primary><secondary>admin tools</secondary></indexterm>Tools for Administrators and Developers</title>
61         <para>Some general debugging tools provided as a part of the standard Linux distro are:</para>
62         <itemizedlist>
63           <listitem>
64             <para><emphasis role="bold">
65                 <literal>strace</literal>
66               </emphasis> . This tool allows a system call to be traced.</para>
67           </listitem>
68           <listitem>
69             <para><emphasis role="bold">
70                 <literal>/var/log/messages</literal>
71               </emphasis> . <literal>syslogd</literal> prints fatal or serious messages at this log.</para>
72           </listitem>
73           <listitem>
74             <para><emphasis role="bold">Crash dumps</emphasis> . On crash-dump enabled kernels, sysrq c produces a crash dump. Lustre enhances this crash dump with a log dump (the last 64 KB of the log) to the console.</para>
75           </listitem>
76           <listitem>
77             <para><emphasis role="bold">
78                 <literal>debugfs</literal>
79               </emphasis>. Interactive file system debugger.</para>
80           </listitem>
81         </itemizedlist>
82         <para>The following logging and data collection tools can be used to collect information for debugging Lustre kernel issues:</para>
83         <itemizedlist>
84           <listitem>
85             <para><emphasis role="bold">
86                 <literal>kdump</literal>
87               </emphasis> . A Linux kernel crash utility useful for debugging a system running Red Hat Enterprise Linux. For more information about <literal>kdump</literal>, see the Red Hat knowledge base article <link xl:href="http://kbase.redhat.com/faq/docs/DOC-6039">How do I configure kexec/kdump on Red Hat Enterprise Linux 5?</link>. To download <literal>kdump</literal>, go to the <link xl:href="http://fedoraproject.org/wiki/SystemConfig/kdump#Download">Fedora Project Download</link> site.</para>
88           </listitem>
89           <listitem>
90             <para><emphasis role="bold">
91                 <literal>netconsole</literal>
92               </emphasis>. Enables kernel-level network logging over UDP. A system requires (SysRq) allows users to collect relevant data through <literal>netconsole</literal>.</para>
93           </listitem>
94           <listitem>
95             <para><emphasis role="bold">
96                 <literal>netdump</literal>
97               </emphasis>. A crash dump utility from Red Hat that allows memory images to be dumped over a network to a central server for analysis. The <literal>netdump</literal> utility was replaced by <literal>kdump</literal> in RHEL 5. For more information about <literal>netdump</literal>, see <link xl:href="http://www.redhat.com/support/wpapers/redhat/netdump/">Red Hat, Inc.&apos;s Network Console and Crash Dump Facility</link>.</para>
98           </listitem>
99         </itemizedlist>
100       </section>
101       <section remap="h4">
102         <title><indexterm><primary>debugging</primary><secondary>developer tools</secondary></indexterm>Tools for Developers</title>
103         <para>The tools described in this section may be useful for debugging Lustre in a development environment.</para>
104         <para>Of general interest is:</para>
105         <itemizedlist>
106           <listitem>
107             <para><literal>
108                 <replaceable role="bold">leak_finder.pl</replaceable>
109               </literal> . This program provided with Lustre is useful for finding memory leaks in the code.</para>
110           </listitem>
111         </itemizedlist>
112         <para>A virtual machine is often used to create an isolated development and test environment. Some commonly-used virtual machines are:</para>
113         <itemizedlist>
114           <listitem>
115             <para><emphasis role="bold">VirtualBox Open Source Edition</emphasis> . Provides enterprise-class virtualization capability for all major platforms and is available free at <link xl:href="http://www.sun.com/software/products/virtualbox/get.jsp?intcmp=2945">Get Sun VirtualBox</link>.</para>
116           </listitem>
117           <listitem>
118             <para><emphasis role="bold">VMware Server</emphasis> . Virtualization platform available as free introductory software at <link xl:href="http://downloads.vmware.com/d/info/datacenter_downloads/vmware_server/2_0">Download VMware Server</link>.</para>
119           </listitem>
120           <listitem>
121             <para><emphasis role="bold">Xen</emphasis> . A para-virtualized environment with virtualization capabilities similar to VMware Server and Virtual Box. However, Xen allows the use of modified kernels to provide near-native performance and the ability to emulate shared storage. For more information, go to <link xl:href="http://xen.org/">xen.org</link>.</para>
122           </listitem>
123         </itemizedlist>
124         <para>A variety of debuggers and analysis tools are available including:</para>
125         <itemizedlist>
126           <listitem>
127             <para><emphasis role="bold">
128                 <literal>kgdb</literal>
129               </emphasis> . The Linux Kernel Source Level Debugger kgdb is used in conjunction with the GNU Debugger <literal>gdb</literal> for debugging the Linux kernel. For more information about using <literal>kgdb</literal> with <literal>gdb</literal>, see <link xl:href="http://www.linuxtopia.org/online_books/redhat_linux_debugging_with_gdb/running.html">Chapter 6. Running Programs Under gdb</link> in the <emphasis>Red Hat Linux 4 Debugging with GDB</emphasis> guide.</para>
130           </listitem>
131           <listitem>
132             <para><emphasis role="bold">
133                 <literal>crash</literal>
134               </emphasis> . Used to analyze saved crash dump data when a system had panicked or locked up or appears unresponsive. For more information about using crash to analyze a crash dump, see:</para>
135             <itemizedlist>
136               <listitem>
137                 <para> Red Hat Magazine article: <link xl:href="http://magazine.redhat.com/2007/08/15/a-quick-overview-of-linux-kernel-crash-dump-analysis/">A quick overview of Linux kernel crash dump analysis</link></para>
138               </listitem>
139               <listitem>
140                 <para><link xl:href="http://people.redhat.com/anderson/crash_whitepaper/#EXAMPLES">Crash Usage: A Case Study</link>  from the white paper <emphasis>Red Hat Crash Utility</emphasis> by David Anderson</para>
141               </listitem>
142               <listitem>
143                 <para> Kernel Trap forum entry: <link xl:href="http://kerneltrap.org/node/5758">Linux: Kernel Crash Dumps</link></para>
144               </listitem>
145               <listitem>
146                 <para> White paper: <link xl:href="http://www.google.com/url?sa=t&amp;source=web&amp;ct=res&amp;cd=8&amp;ved=0CCUQFjAH&amp;url=http%3A%2F%2Fwww.kernel.sg%2Fpapers%2Fcrash-dump-analysis.pdf&amp;rct=j&amp;q=redhat+crash+dump&amp;ei=6aQBS-ifK4T8tAPcjdiHCw&amp;usg=AFQjCNEk03E3GDtAsawG3gfpwc1gGNELAg">A Quick Overview of Linux Kernel Crash Dump Analysis</link></para>
147               </listitem>
148             </itemizedlist>
149           </listitem>
150         </itemizedlist>
151       </section>
152     </section>
153   </section>
154   <section xml:id="dbdoclet.50438274_23607">
155     <title><indexterm><primary>debugging</primary><secondary>procedure</secondary></indexterm>Lustre Debugging Procedures</title>
156     <para>The procedures below may be useful to administrators or developers debugging a Lustre files system.</para>
157     <section remap="h3">
158       <title><indexterm><primary>debugging</primary><secondary>message format</secondary></indexterm>Understanding the Lustre Debug Messaging Format</title>
159       <para>Lustre debug messages are categorized by originating sybsystem, message type, and locaton in the source code. For a list of subsystems and message types, see <xref linkend="dbdoclet.50438274_57603"/>.</para>
160       <note>
161         <para>For a current list of subsystems and debug message types, see <literal>lnet/include/libcfs/libcfs.h</literal> in the Lustre tree</para>
162       </note>
163       <para>The elements of a Lustre debug message are described in <xref linkend="dbdoclet.50438274_57177"/> Format of Lustre Debug Messages.</para>
164       <section xml:id="dbdoclet.50438274_57603">
165         <title>Lustre Debug Messages</title>
166         <para>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:</para>
167         <itemizedlist>
168           <listitem>
169             <para>  Standard Subsystems:</para>
170             <para> mdc, mds, osc, ost, obdclass, obdfilter, llite, ptlrpc, portals, lnd, ldlm, lov</para>
171           </listitem>
172         </itemizedlist>
173         <itemizedlist>
174           <listitem>
175             <para>  Debug Types:</para>
176           </listitem>
177           <listitem>
178             <para><informaltable frame="all">
179                 <tgroup cols="2">
180                   <colspec colname="c1" colwidth="50*"/>
181                   <colspec colname="c2" colwidth="50*"/>
182                   <thead>
183                     <row>
184                       <entry>
185                         <para><emphasis role="bold">Types</emphasis></para>
186                       </entry>
187                       <entry>
188                         <para><emphasis role="bold">Description</emphasis></para>
189                       </entry>
190                     </row>
191                   </thead>
192                   <tbody>
193                     <row>
194                       <entry>
195                         <para> <emphasis role="bold">trace</emphasis></para>
196                       </entry>
197                       <entry>
198                         <para> Entry/Exit markers</para>
199                       </entry>
200                     </row>
201                     <row>
202                       <entry>
203                         <para> <emphasis role="bold">dlmtrace</emphasis></para>
204                       </entry>
205                       <entry>
206                         <para> Locking-related information</para>
207                       </entry>
208                     </row>
209                     <row>
210                       <entry>
211                         <para> <emphasis role="bold">inode</emphasis></para>
212                       </entry>
213                       <entry>
214                         <para> &#160;</para>
215                       </entry>
216                     </row>
217                     <row>
218                       <entry>
219                         <para> <emphasis role="bold">super</emphasis></para>
220                       </entry>
221                       <entry>
222                         <para> &#160;</para>
223                       </entry>
224                     </row>
225                     <row>
226                       <entry>
227                         <para> <emphasis role="bold">ext2</emphasis></para>
228                       </entry>
229                       <entry>
230                         <para> Anything from the ext2_debug</para>
231                       </entry>
232                     </row>
233                     <row>
234                       <entry>
235                         <para> <emphasis role="bold">malloc</emphasis></para>
236                       </entry>
237                       <entry>
238                         <para> Print malloc or free information</para>
239                       </entry>
240                     </row>
241                     <row>
242                       <entry>
243                         <para> <emphasis role="bold">cache</emphasis></para>
244                       </entry>
245                       <entry>
246                         <para> Cache-related information</para>
247                       </entry>
248                     </row>
249                     <row>
250                       <entry>
251                         <para> <emphasis role="bold">info</emphasis></para>
252                       </entry>
253                       <entry>
254                         <para> General information</para>
255                       </entry>
256                     </row>
257                     <row>
258                       <entry>
259                         <para> <emphasis role="bold">ioctl</emphasis></para>
260                       </entry>
261                       <entry>
262                         <para> IOCTL-related information</para>
263                       </entry>
264                     </row>
265                     <row>
266                       <entry>
267                         <para> <emphasis role="bold">blocks</emphasis></para>
268                       </entry>
269                       <entry>
270                         <para> Ext2 block allocation information</para>
271                       </entry>
272                     </row>
273                     <row>
274                       <entry>
275                         <para> <emphasis role="bold">net</emphasis></para>
276                       </entry>
277                       <entry>
278                         <para> Networking</para>
279                       </entry>
280                     </row>
281                     <row>
282                       <entry>
283                         <para> <emphasis role="bold">warning</emphasis></para>
284                       </entry>
285                       <entry>
286                         <para> &#160;</para>
287                       </entry>
288                     </row>
289                     <row>
290                       <entry>
291                         <para> <emphasis role="bold">buffs</emphasis></para>
292                       </entry>
293                       <entry>
294                         <para> &#160;</para>
295                       </entry>
296                     </row>
297                     <row>
298                       <entry>
299                         <para> <emphasis role="bold">other</emphasis></para>
300                       </entry>
301                       <entry>
302                         <para> &#160;</para>
303                       </entry>
304                     </row>
305                     <row>
306                       <entry>
307                         <para> <emphasis role="bold">dentry</emphasis></para>
308                       </entry>
309                       <entry>
310                         <para> &#160;</para>
311                       </entry>
312                     </row>
313                     <row>
314                       <entry>
315                         <para> <emphasis role="bold">portals</emphasis></para>
316                       </entry>
317                       <entry>
318                         <para> Entry/Exit markers</para>
319                       </entry>
320                     </row>
321                     <row>
322                       <entry>
323                         <para> <emphasis role="bold">page</emphasis></para>
324                       </entry>
325                       <entry>
326                         <para> Bulk page handling</para>
327                       </entry>
328                     </row>
329                     <row>
330                       <entry>
331                         <para> <emphasis role="bold">error</emphasis></para>
332                       </entry>
333                       <entry>
334                         <para> Error messages</para>
335                       </entry>
336                     </row>
337                     <row>
338                       <entry>
339                         <para> <emphasis role="bold">emerg</emphasis></para>
340                       </entry>
341                       <entry>
342                         <para> &#160;</para>
343                       </entry>
344                     </row>
345                     <row>
346                       <entry>
347                         <para> <emphasis role="bold">rpctrace</emphasis></para>
348                       </entry>
349                       <entry>
350                         <para> For distributed debugging</para>
351                       </entry>
352                     </row>
353                     <row>
354                       <entry>
355                         <para> <emphasis role="bold">ha</emphasis></para>
356                       </entry>
357                       <entry>
358                         <para> Failover and recovery-related information</para>
359                       </entry>
360                     </row>
361                   </tbody>
362                 </tgroup>
363               </informaltable>
364 </para>
365           </listitem>
366         </itemizedlist>
367       </section>
368       <section xml:id="dbdoclet.50438274_57177">
369         <title>Format of Lustre Debug Messages</title>
370         <para>Lustre uses the <literal>CDEBUG</literal> and <literal>CERROR</literal> macros to print the debug or error messages. To print the message, the <literal>CDEBUG</literal> macro uses <literal>portals_debug_msg</literal> (<literal>portals/linux/oslib/debug.c</literal>). The message format is described below, along with an example.</para>
371         <informaltable frame="all">
372           <tgroup cols="2">
373             <colspec colname="c1" colwidth="50*"/>
374             <colspec colname="c2" colwidth="50*"/>
375             <thead>
376               <row>
377                 <entry>
378                   <para><emphasis role="bold">Parameter</emphasis></para>
379                 </entry>
380                 <entry>
381                   <para><emphasis role="bold">Description</emphasis></para>
382                 </entry>
383               </row>
384             </thead>
385             <tbody>
386               <row>
387                 <entry>
388                   <para> <emphasis role="bold">subsystem</emphasis></para>
389                 </entry>
390                 <entry>
391                   <para> 800000</para>
392                 </entry>
393               </row>
394               <row>
395                 <entry>
396                   <para> <emphasis role="bold">debug mask</emphasis></para>
397                 </entry>
398                 <entry>
399                   <para> 000010</para>
400                 </entry>
401               </row>
402               <row>
403                 <entry>
404                   <para> <emphasis role="bold">smp_processor_id</emphasis></para>
405                 </entry>
406                 <entry>
407                   <para> 0</para>
408                 </entry>
409               </row>
410               <row>
411                 <entry>
412                   <para> <emphasis role="bold">sec.used</emphasis></para>
413                 </entry>
414                 <entry>
415                   <para> 10818808</para>
416                   <para> 47.677302</para>
417                 </entry>
418               </row>
419               <row>
420                 <entry>
421                   <para> <emphasis role="bold">stack size</emphasis></para>
422                 </entry>
423                 <entry>
424                   <para> 1204:</para>
425                 </entry>
426               </row>
427               <row>
428                 <entry>
429                   <para> <emphasis role="bold">pid</emphasis></para>
430                 </entry>
431                 <entry>
432                   <para> 2973:</para>
433                 </entry>
434               </row>
435               <row>
436                 <entry>
437                   <para> <emphasis role="bold">host pid (if uml) or zero</emphasis></para>
438                 </entry>
439                 <entry>
440                   <para> 31070:</para>
441                 </entry>
442               </row>
443               <row>
444                 <entry>
445                   <para> <emphasis role="bold">(file:line #:functional())</emphasis></para>
446                 </entry>
447                 <entry>
448                   <para> (as_dev.c:144:create_write_buffers())</para>
449                 </entry>
450               </row>
451               <row>
452                 <entry>
453                   <para> <emphasis role="bold">debug message</emphasis></para>
454                 </entry>
455                 <entry>
456                   <para> kmalloced &apos;*obj&apos;: 24 at a375571c (tot 17447717)</para>
457                 </entry>
458               </row>
459             </tbody>
460           </tgroup>
461         </informaltable>
462       </section>
463       <section remap="h4">
464         <title>Lustre Debug Messages Buffer</title>
465         <para>Lustre debug messages are maintained in a buffer, with the maximum buffer size specified (in MBs) by the <literal>debug_mb</literal> parameter (<literal>/proc/sys/lnet/debug_mb</literal>). The buffer is circular, so debug messages are kept until the allocated buffer limit is reached, and then the first messages are overwritten.</para>
466       </section>
467     </section>
468     <section xml:id="dbdoclet.50438274_62472">
469       <title><indexterm><primary>debugging</primary><secondary>using lctl</secondary></indexterm>Using the lctl Tool to View Debug Messages</title>
470       <para>The <literal>lctl</literal> tool allows debug messages to be filtered based on subsystems and message types to extract information useful for troubleshooting from a kernel debug log. For a command reference, see <xref linkend="dbdoclet.50438219_38274"/>.</para>
471       <para>You can use <literal>lctl</literal> to:</para>
472       <itemizedlist>
473         <listitem>
474           <para>Obtain a list of all the types and subsystems:</para>
475           <screen>lctl &gt; debug_list <emphasis>&lt;subs | types&gt;</emphasis></screen>
476         </listitem>
477       </itemizedlist>
478       <itemizedlist>
479         <listitem>
480           <para>Filter the debug log:</para>
481           <screen>lctl &gt; filter <emphasis>&lt;subsystem name | debug type&gt;</emphasis></screen>
482         </listitem>
483       </itemizedlist>
484       <note>
485         <para>When <literal>lctl</literal> filters, it removes unwanted lines from the displayed output. This does not affect the contents of the debug log in the kernel&apos;s memory. As a result, you can print the log many times with different filtering levels without worrying about losing data.</para>
486       </note>
487       <itemizedlist>
488         <listitem>
489           <para>Show debug messages belonging to certain subsystem or type:</para>
490           <screen>lctl &gt; show <emphasis>&lt;subsystem name | debug type&gt;</emphasis></screen>
491           <para><literal>debug_kernel</literal> pulls the data from the kernel logs, filters it appropriately, and displays or saves it as per the specified options</para>
492           <screen>lctl &gt; debug_kernel [<emphasis>output filename</emphasis>]</screen>
493           <para>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.</para>
494         </listitem>
495       </itemizedlist>
496       <itemizedlist>
497         <listitem>
498           <para>Filter a log on disk, if you already have a debug log saved to disk (likely from a crash):</para>
499           <screen>lctl &gt; debug_file <emphasis>&lt;input filename&gt;</emphasis> [<emphasis>output filename</emphasis>] </screen>
500           <para>During the debug session, you can add markers or breaks to the log for any reason:</para>
501           <screen>lctl &gt; mark [marker text] </screen>
502           <para>The marker text defaults to the current date and time in the debug log (similar to the example shown below):</para>
503           <screen>DEBUG MARKER: Tue Mar 5 16:06:44 EST 2002 
504 </screen>
505         </listitem>
506       </itemizedlist>
507       <itemizedlist>
508         <listitem>
509           <para>Completely flush the kernel debug buffer:</para>
510           <screen>lctl &gt; clear
511 </screen>
512         </listitem>
513       </itemizedlist>
514       <note>
515         <para>Debug messages displayed with <literal>lctl</literal> are also subject to the kernel debug masks; the filters are additive.</para>
516       </note>
517       <section remap="h4">
518         <title><indexterm><primary>debugging</primary><secondary>lctl example</secondary></indexterm>Sample <literal>lctl</literal> Run</title>
519         <para>Below is a sample run using the <literal>lctl</literal> command.</para>
520         <screen>bash-2.04# ./lctl 
521 lctl &gt; debug_kernel /tmp/lustre_logs/log_all 
522 Debug log: 324 lines, 324 kept, 0 dropped. 
523 lctl &gt; filter trace 
524 Disabling output of type &quot;trace&quot; 
525 lctl &gt; debug_kernel /tmp/lustre_logs/log_notrace 
526 Debug log: 324 lines, 282 kept, 42 dropped. 
527 lctl &gt; show trace 
528 Enabling output of type &quot;trace&quot; 
529 lctl &gt; filter portals 
530 Disabling output from subsystem &quot;portals&quot; 
531 lctl &gt; debug_kernel /tmp/lustre_logs/log_noportals 
532 Debug log: 324 lines, 258 kept, 66 dropped. 
533 </screen>
534       </section>
535     </section>
536     <section remap="h3">
537       <title>Dumping the Buffer to a File (<literal>debug_daemon</literal>)</title>
538       <para>The <literal>debug_daemon</literal> option is used by <literal>lctl</literal> to control the dumping of the <literal>debug_kernel</literal> buffer to a user-specified file. This functionality uses a kernel thread on top of <literal>debug_kernel</literal>, which works in parallel with the <literal>debug_daemon</literal> command.</para>
539       <para>The <literal>debug_daemon</literal> is highly dependent on file system write speed. File system write operations may not be fast enough to flush out all of the <literal>debug_buffer</literal> if the Lustre file system is under heavy system load and continues to <literal>CDEBUG</literal> to the <literal>debug_buffer</literal>. The <literal>debug_daemon</literal> will write the message <literal>DEBUG MARKER:</literal> Trace buffer full into the <literal>debug_buffer</literal> to indicate the <literal>debug_buffer</literal> contents are overlapping before the <literal>debug_daemon</literal> flushes data to a file.</para>
540       <para>Users can use <literal>lctl control</literal> to start or stop the Lustre daemon from dumping the <literal>debug_buffe</literal>r to a file. Users can also temporarily hold daemon from dumping the file. Use of the <literal>debug_daemon</literal> sub-command to <literal>lctl</literal> can provide the same function.</para>
541       <section remap="h4">
542         <title><literal>lctl debug_daemon</literal> Commands</title>
543         <para>This section describes <literal>lctl debug_daemon</literal> commands.</para>
544         <para>To initiate the <literal>debug_daemon</literal> to start dumping <literal>debug_buffer</literal> into a file., enter</para>
545         <screen>$ lctl debug_daemon start [{file} {megabytes}]</screen>
546         <para>The file can be a system default file, as shown in <literal>/proc/sys/lnet/debug_path</literal>. After Lustre starts, the default path is <literal>/tmp/lustre-log-$HOSTNAME</literal>. Users can specify a new filename for <literal>debug_daemon</literal> to output <literal>debug_buffer</literal>. The new file name shows up in <literal>/proc/sys/lnet/debug_path</literal>. Megabytes is the limitation of the file size in MBs.</para>
547         <para>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:</para>
548         <screen>lctl debug_file {file} &gt; {newfile}</screen>
549         <para>The output is internally sorted by the <literal>lct</literal>l command using quicksort.</para>
550         <para>To completely shut down the <literal>debug_daemon</literal> operation and flush the file output, enter:</para>
551         <screen>debug_daemon stop</screen>
552         <para>Otherwise, <literal>debug_daemon</literal> is shut down as part of the Lustre file system shutdown process. Users can restart <literal>debug_daemon</literal> by using start command after each stop command issued.</para>
553         <para>This is an example using <literal>debug_daemon</literal> with the interactive mode of <literal>lctl</literal> to dump debug logs to a 10 MB file.</para>
554         <screen>#~/utils/lctl</screen>
555         <para>To start the daemon to dump debug_buffer into a 40 MB <literal>/tmp/dump</literal> file, enter:</para>
556         <screen>lctl &gt; debug_daemon start /trace/log 40 </screen>
557         <para>To completely shut down the daemon, enter:</para>
558         <screen>lctl &gt; debug_daemon stop </screen>
559         <para>To start another daemon with an unlimited file size, enter:</para>
560         <screen>lctl &gt; debug_daemon start /tmp/unlimited </screen>
561         <para>The text message <literal>*** End of debug_daemon trace log ***</literal> appears at the end of each output file.</para>
562       </section>
563     </section>
564     <section remap="h3">
565       <title><indexterm><primary>debugging</primary><secondary>kernel debug log</secondary></indexterm>Controlling Information Written to the Kernel Debug Log</title>
566       <para>Masks are provided in <literal>/proc/sys/lnet/subsystem_debug</literal> and <literal>/proc/sys/lnet/debug</literal> to be used with the systctl command to determine what information is to be written to the debug log. The subsystem_debug mask determines the information written to the log based on the subsystem (such as iobdfilter, net, portals, or OSC). The debug mask controls information based on debug type (such as info, error, trace, or alloc).</para>
567       <para>To turn off Lustre debugging completely:</para>
568       <screen>sysctl -w lnet.debug=0 </screen>
569       <para>To turn on full Lustre debugging:</para>
570       <screen>sysctl -w lnet.debug=-1 </screen>
571       <para>To turn on logging of messages related to network communications:</para>
572       <screen>sysctl -w lnet.debug=net </screen>
573       <para>To turn on logging of messages related to network communications and existing debug flags:</para>
574       <screen>sysctl -w lnet.debug=+net </screen>
575       <para>To turn off network logging with changing existing flags:</para>
576       <screen>sysctl -w lnet.debug=-net </screen>
577       <para>The various options available to print to kernel debug logs are listed in <literal>lnet/include/libcfs/libcfs.h</literal></para>
578     </section>
579     <section remap="h3">
580       <title><indexterm><primary>debugging</primary><secondary>using strace</secondary></indexterm>Troubleshooting with <literal>strace</literal></title>
581       <para>The <literal>strace</literal> utility provided with the Linux distribution enables system calls to be traced by intercepting all the system calls made by a process and recording the system call name, arguments, and return values.</para>
582       <para>To invoke <literal>strace</literal> on a program, enter:</para>
583       <screen>$ strace <emphasis>&lt;program&gt; &lt;args&gt;</emphasis> </screen>
584       <para>Sometimes, a system call may fork child processes. In this situation, use the <literal>-f</literal> option of <literal>strace</literal> to trace the child processes:</para>
585       <screen>$ strace -f <emphasis>&lt;program&gt; &lt;args&gt;</emphasis> </screen>
586       <para>To redirect the <literal>strace</literal> output to a file, enter:</para>
587       <screen>$ strace -o <emphasis>&lt;filename&gt; &lt;program&gt; &lt;args&gt;</emphasis> </screen>
588       <para>Use the <literal>-ff</literal> option, along with <literal>-o</literal>, to save the trace output in <literal>filename.pid</literal>, where <literal>pid</literal> is the process ID of the process being traced. Use the <literal>-ttt</literal> option to timestamp all lines in the strace output, so they can be correlated to operations in the lustre kernel debug log.</para>
589       <para>If the debugging is done in UML, save the traces on the host machine. In this example, <literal>hostfs</literal> is mounted on <literal>/r</literal>:</para>
590       <screen>$ strace -o /r/tmp/vi.strace </screen>
591     </section>
592     <section remap="h3">
593       <title><indexterm><primary>debugging</primary><secondary>disk contents</secondary></indexterm>Looking at Disk Content</title>
594       <para>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 <literal>lfs</literal> tool can be used to obtain this information for a given file using the <literal>getstripe</literal> subcommand. Use a corresponding <literal>lfs setstripe</literal> command to specify striping attributes for a new file or directory.</para>
595       <para>The <literal>lfs getstripe</literal> 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 <literal>/mnt/lustre/frog</literal> in Lustre file system, run:</para>
596       <screen>$ lfs getstripe /mnt/lustre/frog
597 $
598    obdix                           objid
599    0                               17
600    1                               4
601 </screen>
602       <para>The <literal>debugfs</literal> tool is provided in the <literal>e2fsprogs</literal> package. It can be used for interactive debugging of an <literal>ldiskfs</literal> file system. The <literal>debugfs</literal> 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 <literal>ldiskfs</literal> file system on the OSTs. The file system uses the object IDs as the file names. Once the object IDs are known, use the <literal>debugfs</literal> tool to obtain the attributes of all objects from different OSTs.</para>
603       <para>A sample run for the <literal>/mnt/lustre/frog</literal> file used in the above example is shown here:</para>
604       <screen>     $ debugfs -c /tmp/ost1
605    debugfs: cd O
606    debugfs: cd 0                                   /* for files in group 0 */
607    debugfs: cd d&lt;objid % 32&gt;
608    debugfs: stat &lt;objid&gt;                           /* for getattr on object */
609    debugfs: quit
610 ## Suppose object id is 36, then follow the steps below:
611    $ debugfs /tmp/ost1
612    debugfs: cd O
613    debugfs: cd 0
614    debugfs: cd d4                                  /* objid % 32 */
615    debugfs: stat 36                                /* for getattr on obj 4*/
616    debugfs: dump 36 /tmp/obj.36                    /* dump contents of obj 4 */
617    debugfs: quit</screen>
618     </section>
619     <section remap="h3">
620       <title>Finding the Lustre UUID of an OST</title>
621       <para>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 <literal>debugfs</literal> to get the <literal>last_rcvd</literal> file.</para>
622     </section>
623     <section remap="h3">
624       <title>Printing Debug Messages to the Console</title>
625       <para>To dump debug messages to the console (<literal>/var/log/messages</literal>), set the corresponding debug mask in the <literal>printk</literal> flag:</para>
626       <screen>sysctl -w lnet.printk=-1 </screen>
627       <para>This slows down the system dramatically. It is also possible to selectively enable or disable this capability for particular flags using:</para>
628       <screen>sysctl -w lnet.printk=+vfstrace 
629 sysctl -w lnet.printk=-vfstrace </screen>
630       <para>It is possible to disable warning, error, and console messages, though it is strongly recommended to have something like <literal>lctl debug_daemon</literal> running to capture this data to a local file system for debugging purposes.</para>
631     </section>
632     <section remap="h3">
633       <title>Tracing Lock Traffic</title>
634       <para>Lustre has a specific debug type category for tracing lock traffic. Use:</para>
635       <screen>lctl&gt; filter all_types 
636 lctl&gt; show dlmtrace 
637 lctl&gt; debug_kernel [filename] </screen>
638     </section>
639   </section>
640   <section xml:id="dbdoclet.50438274_80443">
641     <title><indexterm><primary>debugging</primary><secondary>developers tools</secondary></indexterm>Lustre Debugging for Developers</title>
642     <para>The procedures in this section may be useful to developers debugging Lustre code.</para>
643     <section remap="h3">
644       <title>Adding Debugging to the Lustre Source Code</title>
645       <para>The debugging infrastructure provides a number of macros that can be used in Lustre source code to aid in debugging or reporting serious errors.</para>
646       <para>To use these macros, you will need to set the <literal>DEBUG_SUBSYSTEM</literal> variable at the top of the file as shown below:</para>
647       <screen>#define DEBUG_SUBSYSTEM S_PORTALS</screen>
648       <para>A list of available macros with descriptions is provided in the table below.</para>
649       <informaltable frame="all">
650         <tgroup cols="2">
651           <colspec colname="c1" colwidth="50*"/>
652           <colspec colname="c2" colwidth="50*"/>
653           <thead>
654             <row>
655               <entry>
656                 <para><emphasis role="bold">Macro</emphasis></para>
657               </entry>
658               <entry>
659                 <para><emphasis role="bold">Description</emphasis></para>
660               </entry>
661             </row>
662           </thead>
663           <tbody>
664             <row>
665               <entry>
666                 <para> <emphasis role="bold">
667                     <literal>LBUG</literal>
668                   </emphasis></para>
669               </entry>
670               <entry>
671                 <para>A panic-style assertion in the kernel which causes Lustre to dump its circular log to the <literal>/tmp/lustre-log</literal> file. This file can be retrieved after a reboot. LBUG freezes the thread to allow capture of the panic stack. A system reboot is needed to clear the thread.</para>
672               </entry>
673             </row>
674             <row>
675               <entry>
676                 <para> <emphasis role="bold">
677                     <literal>LASSERT</literal>
678                   </emphasis></para>
679               </entry>
680               <entry>
681                 <para>Validates a given expression as true, otherwise calls LBUG. The failed expression is printed on the console, although the values that make up the expression are not printed.</para>
682               </entry>
683             </row>
684             <row>
685               <entry>
686                 <para> <emphasis role="bold">
687                     <literal>LASSERTF</literal>
688                   </emphasis></para>
689               </entry>
690               <entry>
691                 <para>Similar to LASSERT but allows a free-format message to be printed, like <literal>printf/printk</literal>.</para>
692               </entry>
693             </row>
694             <row>
695               <entry>
696                 <para> <emphasis role="bold">
697                     <literal>CDEBUG</literal>
698                   </emphasis></para>
699               </entry>
700               <entry>
701                 <para>The basic, most commonly used debug macro that takes just one more argument than standard <literal>printf</literal> - the debug type. This message adds to the debug log with the debug mask set accordingly. Later, when a user retrieves the log for troubleshooting, they can filter based on this type.</para>
702                 <para><literal>CDEBUG(D_INFO, &quot;This is my debug message: the number is %d\n&quot;, number)</literal>.</para>
703               </entry>
704             </row>
705             <row>
706               <entry>
707                 <para> <emphasis role="bold">
708                     <literal>CERROR</literal>
709                   </emphasis></para>
710               </entry>
711               <entry>
712                 <para> Behaves similarly to <literal>CDEBUG</literal>, but unconditionally prints the message in the debug log and to the console. This is appropriate for serious errors or fatal conditions:</para>
713                 <para><literal>CERROR(&quot;Something very bad has happened, and the return code is %d.\n&quot;, rc);</literal></para>
714               </entry>
715             </row>
716             <row>
717               <entry>
718                 <para> <emphasis role="bold"><literal>ENTRY</literal> and <literal>EXIT</literal></emphasis></para>
719               </entry>
720               <entry>
721                 <para> Add messages to aid in call tracing (takes no arguments). When using these macros, cover all exit conditions to avoid confusion when the debug log reports that a function was entered, but never exited.</para>
722               </entry>
723             </row>
724             <row>
725               <entry>
726                 <para> <emphasis role="bold"><literal>LDLM_DEBUG</literal> and <literal>LDLM_DEBUG_NOLOCK</literal></emphasis></para>
727               </entry>
728               <entry>
729                 <para>Used when tracing MDS and VFS operations for locking. These macros build a thin trace that shows the protocol exchanges between nodes.</para>
730               </entry>
731             </row>
732             <row>
733               <entry>
734                 <para> <literal>
735                     <replaceable role="bold">DEBUG_REQ</replaceable>
736                   </literal></para>
737               </entry>
738               <entry>
739                 <para>Prints information about the given <literal>ptlrpc_request</literal> structure.</para>
740               </entry>
741             </row>
742             <row>
743               <entry>
744                 <para> <literal>
745                     <replaceable role="bold">OBD_FAIL_CHECK</replaceable>
746                   </literal></para>
747               </entry>
748               <entry>
749                 <para>Allows insertion of failure points into the Lustre code. This is useful to generate regression tests that can hit a very specific sequence of events. This works in conjunction with &quot;<literal>sysctl -w lustre.fail_loc={fail_loc}</literal>&quot; to set a specific failure point for which a given <literal>OBD_FAIL_CHECK</literal> will test.</para>
750               </entry>
751             </row>
752             <row>
753               <entry>
754                 <para> <literal>
755                     <replaceable role="bold">OBD_FAIL_TIMEOUT</replaceable>
756                   </literal></para>
757               </entry>
758               <entry>
759                 <para>Similar to <literal>OBD_FAIL_CHECK</literal>. Useful to simulate hung, blocked or busy processes or network devices. If the given <literal>fail_loc</literal> is hit, <literal>OBD_FAIL_TIMEOUT</literal> waits for the specified number of seconds.</para>
760               </entry>
761             </row>
762             <row>
763               <entry>
764                 <para> <literal>
765                     <replaceable role="bold">OBD_RACE</replaceable>
766                   </literal></para>
767               </entry>
768               <entry>
769                 <para>Similar to <literal>OBD_FAIL_CHECK</literal>. Useful to have multiple processes execute the same code concurrently to provoke locking races. The first process to hit <literal>OBD_RACE</literal> sleeps until a second process hits <literal>OBD_RACE</literal>, then both processes continue.</para>
770               </entry>
771             </row>
772             <row>
773               <entry>
774                 <para> <literal>
775                     <replaceable role="bold">OBD_FAIL_ONCE</replaceable>
776                   </literal></para>
777               </entry>
778               <entry>
779                 <para>A flag set on a <literal>lustre.fail_loc</literal> breakpoint to cause the <literal>OBD_FAIL_CHECK</literal> condition to be hit only one time. Otherwise, a <literal>fail_loc</literal> is permanent until it is cleared with &quot;<literal>sysctl -w lustre.fail_loc=0</literal>&quot;.</para>
780               </entry>
781             </row>
782             <row>
783               <entry>
784                 <para><literal>
785                     <replaceable role="bold">OBD_FAIL_RAND</replaceable>
786                   </literal></para>
787               </entry>
788               <entry>
789                 <para>Has <literal>OBD_FAIL_CHECK</literal> fail randomly; on average every (1 / lustre.fail_val) times.</para>
790               </entry>
791             </row>
792             <row>
793               <entry>
794                 <para> <emphasis role="bold">
795                     <literal>OBD_FAIL_SKIP</literal>
796                   </emphasis></para>
797               </entry>
798               <entry>
799                 <para>Has <literal>OBD_FAIL_CHECK</literal> succeed <literal>lustre.fail_val</literal> times, and then fail permanently or once with <literal>OBD_FAIL_ONCE</literal>.</para>
800               </entry>
801             </row>
802             <row>
803               <entry>
804                 <para> <literal>
805                     <replaceable role="bold">OBD_FAIL_SOME</replaceable>
806                   </literal></para>
807               </entry>
808               <entry>
809                 <para>Has <literal>OBD_FAIL_CHECK</literal> fail <literal>lustre.fail_val</literal> times, and then succeed.</para>
810               </entry>
811             </row>
812           </tbody>
813         </tgroup>
814       </informaltable>
815     </section>
816     <section remap="h3">
817       <title>Accessing a <literal>ptlrpc</literal> Request History</title>
818       <para>Each service maintains a request history, which can be useful for first occurrence troubleshooting.</para>
819       <para><literal>ptlrpc</literal> is an RPC protocol layered on LNET that deals with stateful servers and has semantics and built-in support for recovery.</para>
820       <para>A <literal>prlrpc</literal> request history works as follows:</para>
821       <orderedlist>
822         <listitem>
823           <para><literal>request_in_callback()</literal> adds the new request to the service&apos;s request history.</para>
824         </listitem>
825         <listitem>
826           <para>When a request buffer becomes idle, it is added to the service&apos;s request buffer history list.</para>
827         </listitem>
828         <listitem>
829           <para>Buffers are culled from the service&apos;s request buffer history if it has grown above</para>
830           <para><literal>req_buffer_history_max</literal> and its reqs are removed from the service&apos;s request history.</para>
831         </listitem>
832       </orderedlist>
833       <para>Request history is accessed and controlled using the following /proc files under the service directory:</para>
834       <itemizedlist>
835         <listitem>
836           <para><literal>req_buffer_history_len </literal>
837       </para>
838           <para>Number of request buffers currently in the history</para>
839         </listitem>
840       </itemizedlist>
841       <itemizedlist>
842         <listitem>
843           <para><literal>req_buffer_history_max </literal>
844       </para>
845           <para>Maximum number of request buffers to keep</para>
846         </listitem>
847       </itemizedlist>
848       <itemizedlist>
849         <listitem>
850           <para><literal>req_history </literal>
851       </para>
852           <para>The request history</para>
853         </listitem>
854       </itemizedlist>
855       <para>Requests in the history include &quot;live&quot; requests that are currently being handled. Each line in <literal>req_history</literal> looks like:</para>
856       <screen>&lt;seq&gt;:&lt;target NID&gt;:&lt;client ID&gt;:&lt;xid&gt;:&lt;length&gt;:&lt;phase&gt; &lt;svc specific&gt; </screen>
857       <informaltable frame="all">
858         <tgroup cols="2">
859           <colspec colname="c1" colwidth="50*"/>
860           <colspec colname="c2" colwidth="50*"/>
861           <thead>
862             <row>
863               <entry>
864                 <para><emphasis role="bold">Parameter</emphasis></para>
865               </entry>
866               <entry>
867                 <para><emphasis role="bold">Description</emphasis></para>
868               </entry>
869             </row>
870           </thead>
871           <tbody>
872             <row>
873               <entry>
874                 <para> <emphasis role="bold">
875                     <literal>seq</literal>
876                   </emphasis></para>
877               </entry>
878               <entry>
879                 <para> Request sequence number</para>
880               </entry>
881             </row>
882             <row>
883               <entry>
884                 <para> <literal>
885                     <replaceable role="bold">target NID</replaceable>
886                   </literal></para>
887               </entry>
888               <entry>
889                 <para> Destination <literal>NID</literal> of the incoming request</para>
890               </entry>
891             </row>
892             <row>
893               <entry>
894                 <para> <literal>
895                     <replaceable role="bold">client ID</replaceable>
896                   </literal></para>
897               </entry>
898               <entry>
899                 <para> Client <literal>PID</literal> and <literal>NID</literal></para>
900               </entry>
901             </row>
902             <row>
903               <entry>
904                 <para> 
905                         <literal>
906                     <replaceable>xid</replaceable>
907                   </literal>
908                   </para>
909               </entry>
910               <entry>
911                 <para> <literal>rq_xid</literal></para>
912               </entry>
913             </row>
914             <row>
915               <entry>
916                 <para> <emphasis role="bold">
917                     <literal>length</literal>
918                   </emphasis></para>
919               </entry>
920               <entry>
921                 <para> Size of the request message</para>
922               </entry>
923             </row>
924             <row>
925               <entry>
926                 <para> <emphasis role="bold">
927                     <literal>phase</literal>
928                   </emphasis></para>
929               </entry>
930               <entry>
931                 <para><itemizedlist>
932                     <listitem>
933                       <para>New (waiting to be handled or could not be unpacked)</para>
934                     </listitem>
935                     <listitem>
936                       <para>Interpret (unpacked or being handled)</para>
937                     </listitem>
938                     <listitem>
939                       <para>Complete (handled)</para>
940                     </listitem>
941                   </itemizedlist></para>
942               </entry>
943             </row>
944             <row>
945               <entry>
946                 <para> <emphasis role="bold">
947                     <literal>svc specific</literal>
948                   </emphasis></para>
949               </entry>
950               <entry>
951                 <para>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</para>
952               </entry>
953             </row>
954           </tbody>
955         </tgroup>
956       </informaltable>
957     </section>
958     <section remap="h3">
959       <title><indexterm><primary>debugging</primary><secondary>memory leaks</secondary></indexterm>Finding Memory Leaks Using <literal>leak_finder.pl</literal></title>
960       <para>Memory leaks can occur in code when memory has been allocated and then not freed once it is no longer required. The <literal>leak_finder.pl</literal> program provides a way to find memory leaks.</para>
961       <para>Before running this program, you must turn on debugging to collect all <literal>malloc</literal> and free entries. Run:</para>
962       <screen>sysctl -w lnet.debug=+malloc </screen>
963       <para>Then complete the following steps:</para>
964       <orderedlist>
965         <listitem>
966           <para>Dump the log into a user-specified log file using lctl (see <xref linkend="dbdoclet.50438274_62472"/>).</para>
967         </listitem>
968         <listitem>
969           <para>Run the leak finder on the newly-created log dump:</para>
970           <screen>perl leak_finder.pl &lt;ascii-logname&gt;</screen>
971         </listitem>
972       </orderedlist>
973       <para>The output is:</para>
974       <screen>malloced 8bytes at a3116744 (called pathcopy) 
975 (lprocfs_status.c:lprocfs_add_vars:80) 
976 freed 8bytes at a3116744 (called pathcopy) 
977 (lprocfs_status.c:lprocfs_add_vars:80) 
978 </screen>
979       <para>The tool displays the following output to show the leaks found:</para>
980       <screen>Leak:32bytes allocated at a23a8fc(service.c:ptlrpc_init_svc:144,debug file line 241)</screen>
981     </section>
982   </section>
983 </chapter>