1S390 Debug Feature 2================== 3 4files: arch/s390/kernel/debug.c 5 include/asm-s390/debug.h 6 7Description: 8------------ 9The goal of this feature is to provide a kernel debug logging API 10where log records can be stored efficiently in memory, where each component 11(e.g. device drivers) can have one seperate debug log. 12One purpose of this is to inspect the debug logs after a production system crash 13in order to analyze the reason for the crash. 14If the system still runs but only a subcomponent which uses dbf failes, 15it is possible to look at the debug logs on a live system via the Linux proc 16filesystem. 17The debug feature may also very usefull for kernel and driver development. 18 19Design: 20------- 21Kernel components (e.g. device drivers) can register themselves at the debug 22feature with the function call debug_register(). This function initializes a 23debug log for the caller. For each debug log exists a number of debug areas 24where exactly one is active at one time. Each debug area consists of contiguous 25pages in memory. In the debug areas there are stored debug entries (log records) 26which are written by event- and exception-calls. 27 28An event-call writes the specified debug entry to the active debug 29area and updates the log pointer for the active area. If the end 30of the active debug area is reached, a wrap around is done (ring buffer) 31and the next debug entry will be written at the beginning of the active 32debug area. 33 34An exception-call writes the specified debug entry to the log and 35switches to the next debug area. This is done in order to be sure 36that the records which describe the origin of the exception are not 37overwritten when a wrap around for the current area occurs. 38 39The debug areas itselve are also ordered in form of a ring buffer. 40When an exception is thrown in the last debug area, the following debug 41entries are then written again in the very first area. 42 43There are three versions for the event- and exception-calls: One for 44logging raw data, one for text and one for numbers. 45 46Each debug entry contains the following data: 47 48- Timestamp 49- Cpu-Number of calling task 50- Level of debug entry (0...6) 51- Return Address to caller 52- Flag, if entry is an exception or not 53 54The debug logs can be inspected in a live system through entries in 55the proc-filesystem. Under the path /proc/s390dbf there is 56a directory for each registered component, which is named like the 57corresponding component. 58 59The content of the directories are files which represent different views 60to the debug log. Each component can decide which views should be 61used through registering them with the function debug_register_view(). 62Predefined views for hex/ascii, sprintf and raw binary data are provided. 63It is also possible to define other views. The content of 64a view can be inspected simply by reading the corresponding proc file. 65 66All debug logs have an an actual debug level (range from 0 to 6). 67The default level is 3. Event and Exception functions have a 'level' 68parameter. Only debug entries with a level that is lower or equal 69than the actual level are written to the log. This means that high 70priority log entries should have a low level value whereas low priority 71entries should have a high one. 72The actual debug level can be changed with the help of the proc-filesystem 73through writing a number string "x" to the 'level' proc file which is 74provided for every debug log. Debugging can be switched off completely 75by using "-" on the 'level' proc file. 76 77Example: 78 79> echo "-" > /proc/s390dbf/dasd/level 80 81Kernel Interfaces: 82------------------ 83 84---------------------------------------------------------------------------- 85debug_info_t *debug_register(char *name, int pages_index, int nr_areas, 86 int buf_size); 87 88Parameter: name: Name of debug log (e.g. used for proc entry) 89 pages_index: 2^pages_index pages will be allocated per area 90 nr_areas: number of debug areas 91 buf_size: size of data area in each debug entry 92 93Return Value: Handle for generated debug area 94 NULL if register failed 95 96Description: Allocates memory for a debug log 97 Must not be called within an interrupt handler 98 99--------------------------------------------------------------------------- 100void debug_unregister (debug_info_t * id); 101 102Parameter: id: handle for debug log 103 104Return Value: none 105 106Description: frees memory for a debug log 107 Must not be called within an interrupt handler 108 109--------------------------------------------------------------------------- 110void debug_set_level (debug_info_t * id, int new_level); 111 112Parameter: id: handle for debug log 113 new_level: new debug level 114 115Return Value: none 116 117Description: Sets new actual debug level if new_level is valid. 118--------------------------------------------------------------------------- 119debug_entry_t* debug_event (debug_info_t* id, int level, void* data, 120 int length); 121 122Parameter: id: handle for debug log 123 level: debug level 124 data: pointer to data for debug entry 125 length: length of data in bytes 126 127Return Value: Address of written debug entry 128 129Description: writes debug entry to active debug area (if level <= actual 130 debug level) 131 132--------------------------------------------------------------------------- 133debug_entry_t* debug_int_event (debug_info_t * id, int level, 134 unsigned int data); 135debug_entry_t* debug_long_event(debug_info_t * id, int level, 136 unsigned long data); 137 138Parameter: id: handle for debug log 139 level: debug level 140 data: integer value for debug entry 141 142Return Value: Address of written debug entry 143 144Description: writes debug entry to active debug area (if level <= actual 145 debug level) 146 147--------------------------------------------------------------------------- 148debug_entry_t* debug_text_event (debug_info_t * id, int level, 149 const char* data); 150 151Parameter: id: handle for debug log 152 level: debug level 153 data: string for debug entry 154 155Return Value: Address of written debug entry 156 157Description: writes debug entry in ascii format to active debug area 158 (if level <= actual debug level) 159 160--------------------------------------------------------------------------- 161debug_entry_t* debug_sprintf_event (debug_info_t * id, int level, 162 char* string,...); 163 164Parameter: id: handle for debug log 165 level: debug level 166 string: format string for debug entry 167 ...: varargs used as in sprintf() 168 169Return Value: Address of written debug entry 170 171Description: writes debug entry with format string and varargs (longs) to 172 active debug area (if level $<=$ actual debug level). 173 floats and long long datatypes cannot be used as varargs. 174 175--------------------------------------------------------------------------- 176 177debug_entry_t* debug_exception (debug_info_t* id, int level, void* data, 178 int length); 179 180Parameter: id: handle for debug log 181 level: debug level 182 data: pointer to data for debug entry 183 length: length of data in bytes 184 185Return Value: Address of written debug entry 186 187Description: writes debug entry to active debug area (if level <= actual 188 debug level) and switches to next debug area 189 190--------------------------------------------------------------------------- 191debug_entry_t* debug_int_exception (debug_info_t * id, int level, 192 unsigned int data); 193debug_entry_t* debug_long_exception(debug_info_t * id, int level, 194 unsigned long data); 195 196Parameter: id: handle for debug log 197 level: debug level 198 data: integer value for debug entry 199 200Return Value: Address of written debug entry 201 202Description: writes debug entry to active debug area (if level <= actual 203 debug level) and switches to next debug area 204 205--------------------------------------------------------------------------- 206debug_entry_t* debug_text_exception (debug_info_t * id, int level, 207 const char* data); 208 209Parameter: id: handle for debug log 210 level: debug level 211 data: string for debug entry 212 213Return Value: Address of written debug entry 214 215Description: writes debug entry in ascii format to active debug area 216 (if level <= actual debug level) and switches to next debug 217 area 218 219--------------------------------------------------------------------------- 220debug_entry_t* debug_sprintf_exception (debug_info_t * id, int level, 221 char* string,...); 222 223Parameter: id: handle for debug log 224 level: debug level 225 string: format string for debug entry 226 ...: varargs used as in sprintf() 227 228Return Value: Address of written debug entry 229 230Description: writes debug entry with format string and varargs (longs) to 231 active debug area (if level $<=$ actual debug level) and 232 switches to next debug area. 233 floats and long long datatypes cannot be used as varargs. 234 235--------------------------------------------------------------------------- 236 237int debug_register_view (debug_info_t * id, struct debug_view *view); 238 239Parameter: id: handle for debug log 240 view: pointer to debug view struct 241 242Return Value: 0 : ok 243 < 0: Error 244 245Description: registers new debug view and creates proc dir entry 246 247--------------------------------------------------------------------------- 248int debug_unregister_view (debug_info_t * id, struct debug_view *view); 249 250Parameter: id: handle for debug log 251 view: pointer to debug view struct 252 253Return Value: 0 : ok 254 < 0: Error 255 256Description: unregisters debug view and removes proc dir entry 257 258 259 260Predefined views: 261----------------- 262 263extern struct debug_view debug_hex_ascii_view; 264extern struct debug_view debug_raw_view; 265extern struct debug_view debug_sprintf_view; 266 267Examples 268-------- 269 270/* 271 * hex_ascii- + raw-view Example 272 */ 273 274#include <linux/module.h> 275#include <asm/debug.h> 276 277static debug_info_t* debug_info; 278 279int init_module(void) 280{ 281 /* register 4 debug areas with one page each and 4 byte data field */ 282 283 debug_info = debug_register ("test", 0, 4, 4 ); 284 debug_register_view(debug_info,&debug_hex_ascii_view); 285 debug_register_view(debug_info,&debug_raw_view); 286 287 debug_text_event(debug_info, 4 , "one "); 288 debug_int_exception(debug_info, 4, 4711); 289 debug_event(debug_info, 3, &debug_info, 4); 290 291 return 0; 292} 293 294void cleanup_module(void) 295{ 296 debug_unregister (debug_info); 297} 298 299--------------------------------------------------------------------------- 300 301/* 302 * sprintf-view Example 303 */ 304 305#include <linux/module.h> 306#include <asm/debug.h> 307 308static debug_info_t* debug_info; 309 310int init_module(void) 311{ 312 /* register 4 debug areas with one page each and data field for */ 313 /* format string pointer + 2 varargs (= 3 * sizeof(long)) */ 314 315 debug_info = debug_register ("test", 0, 4, sizeof(long) * 3); 316 debug_register_view(debug_info,&debug_sprintf_view); 317 318 debug_sprintf_event(debug_info, 2 , "first event in %s:%i\n",__FILE__,__LINE__); 319 debug_sprintf_exception(debug_info, 1, "pointer to debug info: %p\n",&debug_info); 320 321 return 0; 322} 323 324void cleanup_module(void) 325{ 326 debug_unregister (debug_info); 327} 328 329 330 331ProcFS Interface 332---------------- 333Views to the debug logs can be investigated through reading the corresponding 334proc-files: 335 336Example: 337 338> ls /proc/s390dbf/dasd 339flush hex_ascii level raw 340> cat /proc/s390dbf/dasd/hex_ascii | sort +1 34100 00974733272:680099 2 - 02 0006ad7e 07 ea 4a 90 | .... 34200 00974733272:682210 2 - 02 0006ade6 46 52 45 45 | FREE 34300 00974733272:682213 2 - 02 0006adf6 07 ea 4a 90 | .... 34400 00974733272:682281 1 * 02 0006ab08 41 4c 4c 43 | EXCP 34501 00974733272:682284 2 - 02 0006ab16 45 43 4b 44 | ECKD 34601 00974733272:682287 2 - 02 0006ab28 00 00 00 04 | .... 34701 00974733272:682289 2 - 02 0006ab3e 00 00 00 20 | ... 34801 00974733272:682297 2 - 02 0006ad7e 07 ea 4a 90 | .... 34901 00974733272:684384 2 - 00 0006ade6 46 52 45 45 | FREE 35001 00974733272:684388 2 - 00 0006adf6 07 ea 4a 90 | .... 351 352See section about predefined views for explanation of the above output! 353 354Changing the debug level 355------------------------ 356 357Example: 358 359 360> cat /proc/s390dbf/dasd/level 3613 362> echo "5" > /proc/s390dbf/dasd/level 363> cat /proc/s390dbf/dasd/level 3645 365 366Flushing debug areas 367-------------------- 368Debug areas can be flushed with piping the number of the desired 369area (0...n) to the proc file "flush". When using "-" all debug areas 370are flushed. 371 372Examples: 373 3741. Flush debug area 0: 375> echo "0" > /proc/s390dbf/dasd/flush 376 3772. Flush all debug areas: 378> echo "-" > /proc/s390dbf/dasd/flush 379 380lcrash Interface 381---------------- 382It is planned that the dump analysis tool lcrash gets an additional command 383's390dbf' to display all the debug logs. With this tool it will be possible 384to investigate the debug logs on a live system and with a memory dump after 385a system crash. 386 387Investigating raw memory 388------------------------ 389One last possibility to investigate the debug logs at a live 390system and after a system crash is to look at the raw memory 391under VM or at the Service Element. 392It is possible to find the anker of the debug-logs through 393the 'debug_area_first' symbol in the System map. Then one has 394to follow the correct pointers of the data-structures defined 395in debug.h and find the debug-areas in memory. 396Normally modules which use the debug feature will also have 397a global variable with the pointer to the debug-logs. Following 398this pointer it will also be possible to find the debug logs in 399memory. 400 401For this method it is recommended to use '16 * x + 4' byte (x = 0..n) 402for the length of the data field in debug_register() in 403order to see the debug entries well formatted. 404 405 406Predefined Views 407---------------- 408 409There are three predefined views: hex_ascii, raw and sprintf. 410The hex_ascii view shows the data field in hex and ascii representation 411(e.g. '45 43 4b 44 | ECKD'). 412The raw view returns a bytestream as the debug areas are stored in memory. 413 414The sprintf view formats the debug entries in the same way as the sprintf 415function would do. The sprintf event/expection fuctions write to the 416debug entry a pointer to the format string (size = sizeof(long)) 417and for each vararg a long value. So e.g. for a debug entry with a format 418string plus two varargs one would need to allocate a (3 * sizeof(long)) 419byte data area in the debug_register() function. 420 421 422NOTE: If using the sprintf view do NOT use other event/exception functions 423than the sprintf-event and -exception functions. 424 425The format of the hex_ascii and sprintf view is as follows: 426- Number of area 427- Timestamp (formatted as seconds and microseconds since 00:00:00 Coordinated 428 Universal Time (UTC), January 1, 1970) 429- level of debug entry 430- Exception flag (* = Exception) 431- Cpu-Number of calling task 432- Return Address to caller 433- data field 434 435The format of the raw view is: 436- Header as described in debug.h 437- datafield 438 439A typical line of the hex_ascii view will look like the following (first line 440is only for explanation and will not be displayed when 'cating' the view): 441 442area time level exception cpu caller data (hex + ascii) 443-------------------------------------------------------------------------- 44400 00964419409:440690 1 - 00 88023fe 445 446 447Defining views 448-------------- 449 450Views are specified with the 'debug_view' structure. There are defined 451callback functions which are used for reading and writing the proc files: 452 453struct debug_view { 454 char name[DEBUG_MAX_PROCF_LEN]; 455 debug_prolog_proc_t* prolog_proc; 456 debug_header_proc_t* header_proc; 457 debug_format_proc_t* format_proc; 458 debug_input_proc_t* input_proc; 459 void* private_data; 460}; 461 462where 463 464typedef int (debug_header_proc_t) (debug_info_t* id, 465 struct debug_view* view, 466 int area, 467 debug_entry_t* entry, 468 char* out_buf); 469 470typedef int (debug_format_proc_t) (debug_info_t* id, 471 struct debug_view* view, char* out_buf, 472 const char* in_buf); 473typedef int (debug_prolog_proc_t) (debug_info_t* id, 474 struct debug_view* view, 475 char* out_buf); 476typedef int (debug_input_proc_t) (debug_info_t* id, 477 struct debug_view* view, 478 struct file* file, const char* user_buf, 479 size_t in_buf_size, loff_t* offset); 480 481 482The "private_data" member can be used as pointer to view specific data. 483It is not used by the debug feature itself. 484 485The output when reading a debug-proc file is structured like this: 486 487"prolog_proc output" 488 489"header_proc output 1" "format_proc output 1" 490"header_proc output 2" "format_proc output 2" 491"header_proc output 3" "format_proc output 3" 492... 493 494When a view is read from the proc fs, the Debug Feature calls the 495'prolog_proc' once for writing the prolog. 496Then 'header_proc' and 'format_proc' are called for each 497existing debug entry. 498 499The input_proc can be used to implement functionality when it is written to 500the view (e.g. like with 'echo "0" > /proc/s390dbf/dasd/level). 501 502For header_proc there can be used the default function 503debug_dflt_header_fn() which is defined in in debug.h. 504and which produces the same header output as the predefined views. 505E.g: 50600 00964419409:440761 2 - 00 88023ec 507 508In order to see how to use the callback functions check the implementation 509of the default views! 510 511Example 512 513#include <asm/debug.h> 514 515#define UNKNOWNSTR "data: %08x" 516 517const char* messages[] = 518{"This error...........\n", 519 "That error...........\n", 520 "Problem..............\n", 521 "Something went wrong.\n", 522 "Everything ok........\n", 523 NULL 524}; 525 526static int debug_test_format_fn( 527 debug_info_t * id, struct debug_view *view, 528 char *out_buf, const char *in_buf 529) 530{ 531 int i, rc = 0; 532 533 if(id->buf_size >= 4) { 534 int msg_nr = *((int*)in_buf); 535 if(msg_nr < sizeof(messages)/sizeof(char*) - 1) 536 rc += sprintf(out_buf, "%s", messages[msg_nr]); 537 else 538 rc += sprintf(out_buf, UNKNOWNSTR, msg_nr); 539 } 540 out: 541 return rc; 542} 543 544struct debug_view debug_test_view = { 545 "myview", /* name of view */ 546 NULL, /* no prolog */ 547 &debug_dflt_header_fn, /* default header for each entry */ 548 &debug_test_format_fn, /* our own format function */ 549 NULL, /* no input function */ 550 NULL /* no private data */ 551}; 552 553===== 554test: 555===== 556debug_info_t *debug_info; 557... 558debug_info = debug_register ("test", 0, 4, 4 )); 559debug_register_view(debug_info, &debug_test_view); 560for(i = 0; i < 10; i ++) debug_int_event(debug_info, 1, i); 561 562> cat /proc/s390dbf/test/myview 56300 00964419734:611402 1 - 00 88042ca This error........... 56400 00964419734:611405 1 - 00 88042ca That error........... 56500 00964419734:611408 1 - 00 88042ca Problem.............. 56600 00964419734:611411 1 - 00 88042ca Something went wrong. 56700 00964419734:611414 1 - 00 88042ca Everything ok........ 56800 00964419734:611417 1 - 00 88042ca data: 00000005 56900 00964419734:611419 1 - 00 88042ca data: 00000006 57000 00964419734:611422 1 - 00 88042ca data: 00000007 57100 00964419734:611425 1 - 00 88042ca data: 00000008 57200 00964419734:611428 1 - 00 88042ca data: 00000009 573