0001 ==================
0002 S390 Debug Feature
0003 ==================
0004
0005 files:
0006 - arch/s390/kernel/debug.c
0007 - arch/s390/include/asm/debug.h
0008
0009 Description:
0010 ------------
0011 The goal of this feature is to provide a kernel debug logging API
0012 where log records can be stored efficiently in memory, where each component
0013 (e.g. device drivers) can have one separate debug log.
0014 One purpose of this is to inspect the debug logs after a production system crash
0015 in order to analyze the reason for the crash.
0016
0017 If the system still runs but only a subcomponent which uses dbf fails,
0018 it is possible to look at the debug logs on a live system via the Linux
0019 debugfs filesystem.
0020
0021 The debug feature may also very useful for kernel and driver development.
0022
0023 Design:
0024 -------
0025 Kernel components (e.g. device drivers) can register themselves at the debug
0026 feature with the function call :c:func:`debug_register()`.
0027 This function initializes a
0028 debug log for the caller. For each debug log exists a number of debug areas
0029 where exactly one is active at one time. Each debug area consists of contiguous
0030 pages in memory. In the debug areas there are stored debug entries (log records)
0031 which are written by event- and exception-calls.
0032
0033 An event-call writes the specified debug entry to the active debug
0034 area and updates the log pointer for the active area. If the end
0035 of the active debug area is reached, a wrap around is done (ring buffer)
0036 and the next debug entry will be written at the beginning of the active
0037 debug area.
0038
0039 An exception-call writes the specified debug entry to the log and
0040 switches to the next debug area. This is done in order to be sure
0041 that the records which describe the origin of the exception are not
0042 overwritten when a wrap around for the current area occurs.
0043
0044 The debug areas themselves are also ordered in form of a ring buffer.
0045 When an exception is thrown in the last debug area, the following debug
0046 entries are then written again in the very first area.
0047
0048 There are four versions for the event- and exception-calls: One for
0049 logging raw data, one for text, one for numbers (unsigned int and long),
0050 and one for sprintf-like formatted strings.
0051
0052 Each debug entry contains the following data:
0053
0054 - Timestamp
0055 - Cpu-Number of calling task
0056 - Level of debug entry (0...6)
0057 - Return Address to caller
0058 - Flag, if entry is an exception or not
0059
0060 The debug logs can be inspected in a live system through entries in
0061 the debugfs-filesystem. Under the toplevel directory "``s390dbf``" there is
0062 a directory for each registered component, which is named like the
0063 corresponding component. The debugfs normally should be mounted to
0064 ``/sys/kernel/debug`` therefore the debug feature can be accessed under
0065 ``/sys/kernel/debug/s390dbf``.
0066
0067 The content of the directories are files which represent different views
0068 to the debug log. Each component can decide which views should be
0069 used through registering them with the function :c:func:`debug_register_view()`.
0070 Predefined views for hex/ascii and sprintf data are provided.
0071 It is also possible to define other views. The content of
0072 a view can be inspected simply by reading the corresponding debugfs file.
0073
0074 All debug logs have an actual debug level (range from 0 to 6).
0075 The default level is 3. Event and Exception functions have a :c:data:`level`
0076 parameter. Only debug entries with a level that is lower or equal
0077 than the actual level are written to the log. This means, when
0078 writing events, high priority log entries should have a low level
0079 value whereas low priority entries should have a high one.
0080 The actual debug level can be changed with the help of the debugfs-filesystem
0081 through writing a number string "x" to the ``level`` debugfs file which is
0082 provided for every debug log. Debugging can be switched off completely
0083 by using "-" on the ``level`` debugfs file.
0084
0085 Example::
0086
0087 > echo "-" > /sys/kernel/debug/s390dbf/dasd/level
0088
0089 It is also possible to deactivate the debug feature globally for every
0090 debug log. You can change the behavior using 2 sysctl parameters in
0091 ``/proc/sys/s390dbf``:
0092
0093 There are currently 2 possible triggers, which stop the debug feature
0094 globally. The first possibility is to use the ``debug_active`` sysctl. If
0095 set to 1 the debug feature is running. If ``debug_active`` is set to 0 the
0096 debug feature is turned off.
0097
0098 The second trigger which stops the debug feature is a kernel oops.
0099 That prevents the debug feature from overwriting debug information that
0100 happened before the oops. After an oops you can reactivate the debug feature
0101 by piping 1 to ``/proc/sys/s390dbf/debug_active``. Nevertheless, it's not
0102 suggested to use an oopsed kernel in a production environment.
0103
0104 If you want to disallow the deactivation of the debug feature, you can use
0105 the ``debug_stoppable`` sysctl. If you set ``debug_stoppable`` to 0 the debug
0106 feature cannot be stopped. If the debug feature is already stopped, it
0107 will stay deactivated.
0108
0109 Kernel Interfaces:
0110 ------------------
0111
0112 .. kernel-doc:: arch/s390/kernel/debug.c
0113 .. kernel-doc:: arch/s390/include/asm/debug.h
0114
0115 Predefined views:
0116 -----------------
0117
0118 .. code-block:: c
0119
0120 extern struct debug_view debug_hex_ascii_view;
0121
0122 extern struct debug_view debug_sprintf_view;
0123
0124 Examples
0125 --------
0126
0127 .. code-block:: c
0128
0129 /*
0130 * hex_ascii-view Example
0131 */
0132
0133 #include <linux/init.h>
0134 #include <asm/debug.h>
0135
0136 static debug_info_t *debug_info;
0137
0138 static int init(void)
0139 {
0140 /* register 4 debug areas with one page each and 4 byte data field */
0141
0142 debug_info = debug_register("test", 1, 4, 4 );
0143 debug_register_view(debug_info, &debug_hex_ascii_view);
0144
0145 debug_text_event(debug_info, 4 , "one ");
0146 debug_int_exception(debug_info, 4, 4711);
0147 debug_event(debug_info, 3, &debug_info, 4);
0148
0149 return 0;
0150 }
0151
0152 static void cleanup(void)
0153 {
0154 debug_unregister(debug_info);
0155 }
0156
0157 module_init(init);
0158 module_exit(cleanup);
0159
0160 .. code-block:: c
0161
0162 /*
0163 * sprintf-view Example
0164 */
0165
0166 #include <linux/init.h>
0167 #include <asm/debug.h>
0168
0169 static debug_info_t *debug_info;
0170
0171 static int init(void)
0172 {
0173 /* register 4 debug areas with one page each and data field for */
0174 /* format string pointer + 2 varargs (= 3 * sizeof(long)) */
0175
0176 debug_info = debug_register("test", 1, 4, sizeof(long) * 3);
0177 debug_register_view(debug_info, &debug_sprintf_view);
0178
0179 debug_sprintf_event(debug_info, 2 , "first event in %s:%i\n",__FILE__,__LINE__);
0180 debug_sprintf_exception(debug_info, 1, "pointer to debug info: %p\n",&debug_info);
0181
0182 return 0;
0183 }
0184
0185 static void cleanup(void)
0186 {
0187 debug_unregister(debug_info);
0188 }
0189
0190 module_init(init);
0191 module_exit(cleanup);
0192
0193 Debugfs Interface
0194 -----------------
0195 Views to the debug logs can be investigated through reading the corresponding
0196 debugfs-files:
0197
0198 Example::
0199
0200 > ls /sys/kernel/debug/s390dbf/dasd
0201 flush hex_ascii level pages
0202 > cat /sys/kernel/debug/s390dbf/dasd/hex_ascii | sort -k2,2 -s
0203 00 00974733272:680099 2 - 02 0006ad7e 07 ea 4a 90 | ....
0204 00 00974733272:682210 2 - 02 0006ade6 46 52 45 45 | FREE
0205 00 00974733272:682213 2 - 02 0006adf6 07 ea 4a 90 | ....
0206 00 00974733272:682281 1 * 02 0006ab08 41 4c 4c 43 | EXCP
0207 01 00974733272:682284 2 - 02 0006ab16 45 43 4b 44 | ECKD
0208 01 00974733272:682287 2 - 02 0006ab28 00 00 00 04 | ....
0209 01 00974733272:682289 2 - 02 0006ab3e 00 00 00 20 | ...
0210 01 00974733272:682297 2 - 02 0006ad7e 07 ea 4a 90 | ....
0211 01 00974733272:684384 2 - 00 0006ade6 46 52 45 45 | FREE
0212 01 00974733272:684388 2 - 00 0006adf6 07 ea 4a 90 | ....
0213
0214 See section about predefined views for explanation of the above output!
0215
0216 Changing the debug level
0217 ------------------------
0218
0219 Example::
0220
0221
0222 > cat /sys/kernel/debug/s390dbf/dasd/level
0223 3
0224 > echo "5" > /sys/kernel/debug/s390dbf/dasd/level
0225 > cat /sys/kernel/debug/s390dbf/dasd/level
0226 5
0227
0228 Flushing debug areas
0229 --------------------
0230 Debug areas can be flushed with piping the number of the desired
0231 area (0...n) to the debugfs file "flush". When using "-" all debug areas
0232 are flushed.
0233
0234 Examples:
0235
0236 1. Flush debug area 0::
0237
0238 > echo "0" > /sys/kernel/debug/s390dbf/dasd/flush
0239
0240 2. Flush all debug areas::
0241
0242 > echo "-" > /sys/kernel/debug/s390dbf/dasd/flush
0243
0244 Changing the size of debug areas
0245 ------------------------------------
0246 It is possible the change the size of debug areas through piping
0247 the number of pages to the debugfs file "pages". The resize request will
0248 also flush the debug areas.
0249
0250 Example:
0251
0252 Define 4 pages for the debug areas of debug feature "dasd"::
0253
0254 > echo "4" > /sys/kernel/debug/s390dbf/dasd/pages
0255
0256 Stopping the debug feature
0257 --------------------------
0258 Example:
0259
0260 1. Check if stopping is allowed::
0261
0262 > cat /proc/sys/s390dbf/debug_stoppable
0263
0264 2. Stop debug feature::
0265
0266 > echo 0 > /proc/sys/s390dbf/debug_active
0267
0268 crash Interface
0269 ----------------
0270 The ``crash`` tool since v5.1.0 has a built-in command
0271 ``s390dbf`` to display all the debug logs or export them to the file system.
0272 With this tool it is possible
0273 to investigate the debug logs on a live system and with a memory dump after
0274 a system crash.
0275
0276 Investigating raw memory
0277 ------------------------
0278 One last possibility to investigate the debug logs at a live
0279 system and after a system crash is to look at the raw memory
0280 under VM or at the Service Element.
0281 It is possible to find the anchor of the debug-logs through
0282 the ``debug_area_first`` symbol in the System map. Then one has
0283 to follow the correct pointers of the data-structures defined
0284 in debug.h and find the debug-areas in memory.
0285 Normally modules which use the debug feature will also have
0286 a global variable with the pointer to the debug-logs. Following
0287 this pointer it will also be possible to find the debug logs in
0288 memory.
0289
0290 For this method it is recommended to use '16 * x + 4' byte (x = 0..n)
0291 for the length of the data field in :c:func:`debug_register()` in
0292 order to see the debug entries well formatted.
0293
0294
0295 Predefined Views
0296 ----------------
0297
0298 There are two predefined views: hex_ascii and sprintf.
0299 The hex_ascii view shows the data field in hex and ascii representation
0300 (e.g. ``45 43 4b 44 | ECKD``).
0301
0302 The sprintf view formats the debug entries in the same way as the sprintf
0303 function would do. The sprintf event/exception functions write to the
0304 debug entry a pointer to the format string (size = sizeof(long))
0305 and for each vararg a long value. So e.g. for a debug entry with a format
0306 string plus two varargs one would need to allocate a (3 * sizeof(long))
0307 byte data area in the debug_register() function.
0308
0309 IMPORTANT:
0310 Using "%s" in sprintf event functions is dangerous. You can only
0311 use "%s" in the sprintf event functions, if the memory for the passed string
0312 is available as long as the debug feature exists. The reason behind this is
0313 that due to performance considerations only a pointer to the string is stored
0314 in the debug feature. If you log a string that is freed afterwards, you will
0315 get an OOPS when inspecting the debug feature, because then the debug feature
0316 will access the already freed memory.
0317
0318 NOTE:
0319 If using the sprintf view do NOT use other event/exception functions
0320 than the sprintf-event and -exception functions.
0321
0322 The format of the hex_ascii and sprintf view is as follows:
0323
0324 - Number of area
0325 - Timestamp (formatted as seconds and microseconds since 00:00:00 Coordinated
0326 Universal Time (UTC), January 1, 1970)
0327 - level of debug entry
0328 - Exception flag (* = Exception)
0329 - Cpu-Number of calling task
0330 - Return Address to caller
0331 - data field
0332
0333 A typical line of the hex_ascii view will look like the following (first line
0334 is only for explanation and will not be displayed when 'cating' the view)::
0335
0336 area time level exception cpu caller data (hex + ascii)
0337 --------------------------------------------------------------------------
0338 00 00964419409:440690 1 - 00 88023fe
0339
0340
0341 Defining views
0342 --------------
0343
0344 Views are specified with the 'debug_view' structure. There are defined
0345 callback functions which are used for reading and writing the debugfs files:
0346
0347 .. code-block:: c
0348
0349 struct debug_view {
0350 char name[DEBUG_MAX_PROCF_LEN];
0351 debug_prolog_proc_t* prolog_proc;
0352 debug_header_proc_t* header_proc;
0353 debug_format_proc_t* format_proc;
0354 debug_input_proc_t* input_proc;
0355 void* private_data;
0356 };
0357
0358 where:
0359
0360 .. code-block:: c
0361
0362 typedef int (debug_header_proc_t) (debug_info_t* id,
0363 struct debug_view* view,
0364 int area,
0365 debug_entry_t* entry,
0366 char* out_buf);
0367
0368 typedef int (debug_format_proc_t) (debug_info_t* id,
0369 struct debug_view* view, char* out_buf,
0370 const char* in_buf);
0371 typedef int (debug_prolog_proc_t) (debug_info_t* id,
0372 struct debug_view* view,
0373 char* out_buf);
0374 typedef int (debug_input_proc_t) (debug_info_t* id,
0375 struct debug_view* view,
0376 struct file* file, const char* user_buf,
0377 size_t in_buf_size, loff_t* offset);
0378
0379
0380 The "private_data" member can be used as pointer to view specific data.
0381 It is not used by the debug feature itself.
0382
0383 The output when reading a debugfs file is structured like this::
0384
0385 "prolog_proc output"
0386
0387 "header_proc output 1" "format_proc output 1"
0388 "header_proc output 2" "format_proc output 2"
0389 "header_proc output 3" "format_proc output 3"
0390 ...
0391
0392 When a view is read from the debugfs, the Debug Feature calls the
0393 'prolog_proc' once for writing the prolog.
0394 Then 'header_proc' and 'format_proc' are called for each
0395 existing debug entry.
0396
0397 The input_proc can be used to implement functionality when it is written to
0398 the view (e.g. like with ``echo "0" > /sys/kernel/debug/s390dbf/dasd/level``).
0399
0400 For header_proc there can be used the default function
0401 :c:func:`debug_dflt_header_fn()` which is defined in debug.h.
0402 and which produces the same header output as the predefined views.
0403 E.g::
0404
0405 00 00964419409:440761 2 - 00 88023ec
0406
0407 In order to see how to use the callback functions check the implementation
0408 of the default views!
0409
0410 Example:
0411
0412 .. code-block:: c
0413
0414 #include <asm/debug.h>
0415
0416 #define UNKNOWNSTR "data: %08x"
0417
0418 const char* messages[] =
0419 {"This error...........\n",
0420 "That error...........\n",
0421 "Problem..............\n",
0422 "Something went wrong.\n",
0423 "Everything ok........\n",
0424 NULL
0425 };
0426
0427 static int debug_test_format_fn(
0428 debug_info_t *id, struct debug_view *view,
0429 char *out_buf, const char *in_buf
0430 )
0431 {
0432 int i, rc = 0;
0433
0434 if (id->buf_size >= 4) {
0435 int msg_nr = *((int*)in_buf);
0436 if (msg_nr < sizeof(messages) / sizeof(char*) - 1)
0437 rc += sprintf(out_buf, "%s", messages[msg_nr]);
0438 else
0439 rc += sprintf(out_buf, UNKNOWNSTR, msg_nr);
0440 }
0441 return rc;
0442 }
0443
0444 struct debug_view debug_test_view = {
0445 "myview", /* name of view */
0446 NULL, /* no prolog */
0447 &debug_dflt_header_fn, /* default header for each entry */
0448 &debug_test_format_fn, /* our own format function */
0449 NULL, /* no input function */
0450 NULL /* no private data */
0451 };
0452
0453 test:
0454 =====
0455
0456 .. code-block:: c
0457
0458 debug_info_t *debug_info;
0459 int i;
0460 ...
0461 debug_info = debug_register("test", 0, 4, 4);
0462 debug_register_view(debug_info, &debug_test_view);
0463 for (i = 0; i < 10; i ++)
0464 debug_int_event(debug_info, 1, i);
0465
0466 ::
0467
0468 > cat /sys/kernel/debug/s390dbf/test/myview
0469 00 00964419734:611402 1 - 00 88042ca This error...........
0470 00 00964419734:611405 1 - 00 88042ca That error...........
0471 00 00964419734:611408 1 - 00 88042ca Problem..............
0472 00 00964419734:611411 1 - 00 88042ca Something went wrong.
0473 00 00964419734:611414 1 - 00 88042ca Everything ok........
0474 00 00964419734:611417 1 - 00 88042ca data: 00000005
0475 00 00964419734:611419 1 - 00 88042ca data: 00000006
0476 00 00964419734:611422 1 - 00 88042ca data: 00000007
0477 00 00964419734:611425 1 - 00 88042ca data: 00000008
0478 00 00964419734:611428 1 - 00 88042ca data: 00000009
