S390 Debug Feature

S390 Debug Feature

S390 Debug Feature의 구현과 공개 인터페이스는 `arch/s390/kernel/debug.c`와 `arch/s390/include/asm/debug.h`에 있습니다.

목적과 사용 환경

이 기능의 목표는 log record를 메모리에 효율적으로 저장하고 device driver 같은 각 component가 별도의 debug log를 가질 수 있게 하는 kernel debug logging API를 제공하는 것입니다.

주요 용도는 production system crash 뒤 debug log를 조사해 crash 원인을 분석하는 것입니다. 시스템은 계속 실행 중이지만 DBF를 사용하는 하위 component만 실패한 경우에는 Linux debugfs filesystem을 통해 live system에서 log를 볼 수 있습니다.

kernel 및 driver 개발에도 이 debug feature를 활용할 수 있습니다.

debug area와 ring buffer 설계

kernel component는 `debug_register()`를 호출해 자신을 debug feature에 등록합니다. 이 함수는 호출자를 위한 debug log를 초기화합니다. 각 log에는 여러 debug area가 있고 그중 정확히 하나만 한 시점에 active 상태입니다. 각 area는 메모리의 연속 page로 구성되며 event 호출과 exception 호출이 기록하는 debug entry를 저장합니다.

event 호출은 지정한 entry를 active area에 쓰고 해당 area의 log pointer를 갱신합니다. active area 끝에 도달하면 ring buffer처럼 처음으로 wrap around하여 다음 entry를 active area 시작에 씁니다.

exception 호출은 entry를 log에 쓴 뒤 다음 debug area로 전환합니다. 이는 현재 area가 wrap around하더라도 exception의 원인을 설명하는 record가 덮어써지지 않게 합니다. debug area 자체도 ring buffer로 배열되므로 마지막 area에서 exception이 발생하면 이후 entry는 첫 area에 다시 기록됩니다.

event와 exception 호출은 raw data, text, `unsigned int`와 `long` 숫자, sprintf 형식 문자열을 위한 네 종류로 제공됩니다.

entry 필드와 debugfs view

각 debug entry에는 다음 정보가 들어 있습니다.

• Timestamp
• 호출 task의 CPU 번호
• debug entry level `0...6`
• 호출자로 돌아갈 return address
• entry가 exception인지 나타내는 flag

live system에서는 debugfs 항목으로 log를 조사합니다. 최상위 `s390dbf` 아래에 등록된 component마다 같은 이름의 디렉터리가 생깁니다. debugfs는 보통 `/sys/kernel/debug`에 mount하므로 접근 경로는 `/sys/kernel/debug/s390dbf`입니다.

component 디렉터리의 파일은 debug log를 표현하는 서로 다른 view입니다. component는 `debug_register_view()`로 사용할 view를 등록합니다. hex/ascii와 sprintf 데이터를 위한 사전 정의 view가 제공되며 사용자 정의 view도 만들 수 있습니다. 대응 debugfs 파일을 읽으면 view 내용을 확인할 수 있습니다.

debug level과 전역 중지 제어

모든 debug log의 현재 level 범위는 0부터 6이며 기본값은 3입니다. event와 exception 함수의 `level` 인수가 현재 level 이하일 때만 entry가 기록됩니다. 따라서 우선순위가 높은 log entry에는 낮은 level 값을, 우선순위가 낮은 entry에는 높은 값을 사용해야 합니다.

각 log의 `level` debugfs 파일에 숫자 문자열 `x`를 쓰면 현재 level을 바꿉니다. `-`를 쓰면 해당 log의 debugging을 완전히 끕니다.

> echo "-" > /sys/kernel/debug/s390dbf/dasd/level

모든 debug log를 전역으로 비활성화하는 동작은 `/proc/sys/s390dbf`의 두 sysctl로 제어합니다. `debug_active=1`이면 실행 중이고 `debug_active=0`이면 꺼집니다.

두 번째 전역 중지 trigger는 kernel oops입니다. oops 전의 debug 정보를 덮어쓰지 않도록 기록을 멈춥니다. 이후 `/proc/sys/s390dbf/debug_active`에 1을 쓰면 다시 활성화할 수 있지만, oops가 발생한 kernel을 production 환경에서 계속 사용하는 것은 권장하지 않습니다.

`debug_stoppable=0`으로 설정하면 debug feature의 비활성화를 금지합니다. 단, 이미 중지된 상태라면 비활성 상태를 유지합니다.

kernel-doc와 사전 정의 view

kernel interface 문서는 `arch/s390/kernel/debug.c`와 `arch/s390/include/asm/debug.h`에서 kernel-doc로 가져옵니다.

사전 정의 view 두 개는 다음과 같이 선언됩니다.

extern struct debug_view debug_hex_ascii_view;

extern struct debug_view debug_sprintf_view;

hex_ascii와 sprintf 등록 예제

첫 번째 예제는 각각 한 page인 debug area 4개와 4 byte data field를 가진 `test` log를 등록하고 `debug_hex_ascii_view`를 연결합니다. 이어 text event, integer exception, raw event를 기록하고 module 정리 시 unregister합니다.

/*
 * hex_ascii-view Example
 */

#include <linux/init.h>
#include <asm/debug.h>

static debug_info_t *debug_info;

static int init(void)
{
    /* register 4 debug areas with one page each and 4 byte data field */

    debug_info = debug_register("test", 1, 4, 4 );
    debug_register_view(debug_info, &debug_hex_ascii_view);

    debug_text_event(debug_info, 4 , "one ");
    debug_int_exception(debug_info, 4, 4711);
    debug_event(debug_info, 3, &debug_info, 4);

    return 0;
}

static void cleanup(void)
{
    debug_unregister(debug_info);
}

module_init(init);
module_exit(cleanup);

두 번째 예제는 format string pointer와 vararg 두 개를 담도록 `sizeof(long) * 3` 크기의 data field를 만들고 `debug_sprintf_view`를 연결합니다. `debug_sprintf_event()`와 `debug_sprintf_exception()`이 형식화 entry를 기록합니다.

/*
 * sprintf-view Example
 */

#include <linux/init.h>
#include <asm/debug.h>

static debug_info_t *debug_info;

static int init(void)
{
    /* register 4 debug areas with one page each and data field for */
    /* format string pointer + 2 varargs (= 3 * sizeof(long))       */

    debug_info = debug_register("test", 1, 4, sizeof(long) * 3);
    debug_register_view(debug_info, &debug_sprintf_view);

    debug_sprintf_event(debug_info, 2 , "first event in %s:%i\n",__FILE__,__LINE__);
    debug_sprintf_exception(debug_info, 1, "pointer to debug info: %p\n",&debug_info);

    return 0;
}

static void cleanup(void)
{
    debug_unregister(debug_info);
}

module_init(init);
module_exit(cleanup);

debugfs log 조회

대응 debugfs 파일을 읽어 debug log view를 조사합니다. 다음 예는 DASD log 디렉터리의 `flush`, `hex_ascii`, `level`, `pages` 파일을 나열하고, `hex_ascii` view를 timestamp 열 기준으로 안정 정렬해 표시합니다.

> ls /sys/kernel/debug/s390dbf/dasd
flush  hex_ascii  level pages
> cat /sys/kernel/debug/s390dbf/dasd/hex_ascii | sort -k2,2 -s
00 00974733272:680099 2 - 02 0006ad7e  07 ea 4a 90 | ....
00 00974733272:682210 2 - 02 0006ade6  46 52 45 45 | FREE
00 00974733272:682213 2 - 02 0006adf6  07 ea 4a 90 | ....
00 00974733272:682281 1 * 02 0006ab08  41 4c 4c 43 | EXCP
01 00974733272:682284 2 - 02 0006ab16  45 43 4b 44 | ECKD
01 00974733272:682287 2 - 02 0006ab28  00 00 00 04 | ....
01 00974733272:682289 2 - 02 0006ab3e  00 00 00 20 | ...
01 00974733272:682297 2 - 02 0006ad7e  07 ea 4a 90 | ....
01 00974733272:684384 2 - 00 0006ade6  46 52 45 45 | FREE
01 00974733272:684388 2 - 00 0006adf6  07 ea 4a 90 | ....

각 출력 열의 의미는 아래 사전 정의 view 절에서 설명합니다.

debug level 변경

다음 예는 DASD debug log의 현재 level 3을 확인한 뒤 5를 쓰고 변경 결과를 다시 확인합니다.

> cat /sys/kernel/debug/s390dbf/dasd/level
3
> echo "5" > /sys/kernel/debug/s390dbf/dasd/level
> cat /sys/kernel/debug/s390dbf/dasd/level
5

debug area 비우기

`flush` debugfs 파일에 원하는 area 번호 `0...n`을 쓰면 해당 area를 비웁니다. `-`를 쓰면 모든 debug area를 비웁니다.

debug area 크기 변경

`pages` debugfs 파일에 page 수를 쓰면 debug area 크기를 바꿀 수 있습니다. resize 요청은 debug area도 함께 비웁니다. 다음 예는 `dasd` debug feature의 area 크기를 4 page로 정합니다.

> echo "4" > /sys/kernel/debug/s390dbf/dasd/pages

debug feature 중지

중지 허용 여부는 `debug_stoppable`에서 확인하고, `debug_active`에 0을 쓰면 debug feature를 중지합니다.

> cat /proc/sys/s390dbf/debug_stoppable
> echo 0 > /proc/sys/s390dbf/debug_active

crash 도구 인터페이스

`crash` 도구는 v5.1.0부터 모든 debug log를 표시하거나 filesystem으로 export하는 내장 명령 `s390dbf`를 제공합니다. live system뿐 아니라 system crash 뒤 memory dump에서도 log를 조사할 수 있습니다.

raw memory 조사

live system과 system crash 뒤 VM 또는 Service Element에서 raw memory를 직접 확인하는 방법도 있습니다. System map의 `debug_area_first` symbol로 debug log anchor를 찾은 뒤 `debug.h`에 정의된 data structure의 올바른 pointer를 따라가 debug area를 찾습니다.

debug feature를 사용하는 module은 보통 debug log pointer를 담은 global variable도 가지므로 이 pointer를 따라가 log를 찾을 수 있습니다.

사전 정의 hex_ascii와 sprintf view

사전 정의 view는 `hex_ascii`와 `sprintf` 두 개입니다. `hex_ascii`는 data field를 `45 43 4b 44 | ECKD`처럼 16진수와 ASCII로 표시합니다.

`sprintf` view는 `sprintf` 함수와 같은 방식으로 entry를 형식화합니다. sprintf event/exception 함수는 format string pointer 하나와 각 vararg의 `long` 값을 entry에 씁니다. 따라서 format string과 vararg 두 개를 담으려면 `debug_register()`에서 `3 * sizeof(long)` byte data area를 할당해야 합니다.

view 출력 형식

`hex_ascii`와 `sprintf` view는 다음 필드를 순서대로 출력합니다.

다음은 전형적인 `hex_ascii` 한 줄입니다. 첫 줄의 field 이름은 설명을 위한 것이며 실제 view를 `cat`할 때는 표시되지 않습니다.

area  time           level exception cpu caller    data (hex + ascii)
--------------------------------------------------------------------------
00    00964419409:440690 1 -         00  88023fe

debug_view와 callback 형식

view는 `debug_view` 구조체로 지정하며 debugfs 파일의 읽기와 쓰기에 사용할 callback을 담습니다.

struct debug_view {
      char name[DEBUG_MAX_PROCF_LEN];
      debug_prolog_proc_t* prolog_proc;
      debug_header_proc_t* header_proc;
      debug_format_proc_t* format_proc;
      debug_input_proc_t*  input_proc;
      void*                private_data;
};

각 callback type은 다음 원형을 사용합니다.

typedef int (debug_header_proc_t) (debug_info_t* id,
                                   struct debug_view* view,
                                   int area,
                                   debug_entry_t* entry,
                                   char* out_buf);

typedef int (debug_format_proc_t) (debug_info_t* id,
                                   struct debug_view* view, char* out_buf,
                                   const char* in_buf);
typedef int (debug_prolog_proc_t) (debug_info_t* id,
                                   struct debug_view* view,
                                   char* out_buf);
typedef int (debug_input_proc_t) (debug_info_t* id,
                                  struct debug_view* view,
                                  struct file* file, const char* user_buf,
                                  size_t in_buf_size, loff_t* offset);

`private_data` member는 view 전용 data를 가리키는 pointer로 사용할 수 있으며 debug feature 자체는 이 값을 사용하지 않습니다.

view 읽기·쓰기 callback 흐름

debugfs 파일을 읽을 때 출력은 다음 구조로 생성됩니다.

view를 읽으면 Debug Feature가 `prolog_proc`를 한 번 호출해 prolog를 쓰고, 각 기존 debug entry마다 `header_proc`와 `format_proc`를 호출합니다.

`input_proc`는 view에 데이터를 쓸 때 동작을 구현합니다. 예를 들어 `echo "0" > /sys/kernel/debug/s390dbf/dasd/level` 같은 입력을 처리할 수 있습니다.

`header_proc`에는 `debug.h`의 기본 함수 `debug_dflt_header_fn()`을 사용할 수 있습니다. 이 함수는 사전 정의 view와 같은 header 출력을 만듭니다.

00 00964419409:440761 2 - 00 88023ec

callback 사용법은 기본 view 구현을 참고하십시오.

사용자 정의 view 예제

예제의 `debug_test_format_fn()`은 data field의 첫 4 byte를 message 번호로 읽습니다. 번호가 `messages` 배열 범위 안이면 대응 문자열을 출력하고, 범위를 벗어나면 `UNKNOWNSTR` 형식으로 번호를 출력합니다.

`debug_test_view`는 이름을 `myview`로 지정하고 prolog와 input callback 없이 기본 header callback과 사용자 정의 format callback을 연결합니다.

#include <asm/debug.h>

#define UNKNOWNSTR "data: %08x"

const char* messages[] =
{"This error...........\n",
 "That error...........\n",
 "Problem..............\n",
 "Something went wrong.\n",
 "Everything ok........\n",
 NULL
};

static int debug_test_format_fn(
   debug_info_t *id, struct debug_view *view,
   char *out_buf, const char *in_buf
)
{
  int i, rc = 0;

  if (id->buf_size >= 4) {
     int msg_nr = *((int*)in_buf);
     if (msg_nr < sizeof(messages) / sizeof(char*) - 1)
        rc += sprintf(out_buf, "%s", messages[msg_nr]);
     else
        rc += sprintf(out_buf, UNKNOWNSTR, msg_nr);
  }
  return rc;
}

struct debug_view debug_test_view = {
  "myview",                 /* name of view */
  NULL,                     /* no prolog */
  &debug_dflt_header_fn,    /* default header for each entry */
  &debug_test_format_fn,    /* our own format function */
  NULL,                     /* no input function */
  NULL                      /* no private data */
};

사용자 정의 view 시험과 출력

시험 코드는 area당 4 page, 4 byte data field를 가진 `test` log를 등록하고 `myview`를 연결한 뒤 정수 0부터 9까지를 level 1 event로 기록합니다.

debug_info_t *debug_info;
int i;
...
debug_info = debug_register("test", 0, 4, 4);
debug_register_view(debug_info, &debug_test_view);
for (i = 0; i < 10; i ++)
  debug_int_event(debug_info, 1, i);

`/sys/kernel/debug/s390dbf/test/myview`를 읽으면 0부터 4까지는 `messages`의 문자열로, 5부터 9까지는 `data: 0000000N` 형식으로 출력됩니다.

> cat /sys/kernel/debug/s390dbf/test/myview
00 00964419734:611402 1 - 00 88042ca   This error...........
00 00964419734:611405 1 - 00 88042ca   That error...........
00 00964419734:611408 1 - 00 88042ca   Problem..............
00 00964419734:611411 1 - 00 88042ca   Something went wrong.
00 00964419734:611414 1 - 00 88042ca   Everything ok........
00 00964419734:611417 1 - 00 88042ca   data: 00000005
00 00964419734:611419 1 - 00 88042ca   data: 00000006
00 00964419734:611422 1 - 00 88042ca   data: 00000007
00 00964419734:611425 1 - 00 88042ca   data: 00000008
00 00964419734:611428 1 - 00 88042ca   data: 00000009