문제 해결 메모 (아직 공개되지 않은 정보가 포함될 수 있기 때문에 결과를 부분적으로 모호하게 할 수 있음)

현상

DB 서버에서 작업을 수행하면 STANDBY 서버의 CPU 사용률이 높아집니다.

초동

항상 느리고 어떤 거래의 지연이 2배, 오류라고 생각하는 것과 달리 CPU 사용률이 높아지는 현상은 명확하다.그러나 현상을 설명하기에는 아직 구체적이지 않다. (원래 CPU 사용률이 높아지는 것 자체가 나쁜 것은 아니다. 오히려 IO를 기다리지 않고 효과적으로 일할 수 있는 좋은 징조일 수도 있다. 이런 상황에서 무슨 쓸모없는 처리를 했는지 뚜렷하게 상상된다.)
한 마디로 하면 고장 진단 초기에 중요한 것은 사건을 정확하고 구체적으로 기술하는 것이다(5W1H 깊이 발굴).
우선 확인해야 할 요점은 다음과 같다.

구체적인 CPU 사용률(HOW)

CPU(WHO)

를 사용하는 프로세스는 구체적으로 무엇입니까

CPU 포화, 사용자 공간 또는 코어 공간(WHERE·WHAT)

그 현상은 언제 일어날까(WHEN)→이 상황에서 바로 지금 이 순간, 계기가 되는 동작은 무엇인가

시스템의 어떤 구성 요소에서 발생(WHERE) → 이 경우 STANDBY의 DB 서버

왜 이 사건이 발생했는지(WHY) → 이런 상황에서 우선 이 점을 명확히 하는 목표(진정한 목표는 당연히 사건의 해소·해결)

어떤 프로세스가 프로세서를 얼마나 사용했는지

이것은 OS의 top 명령 또는 pidstat 명령을 통해 관측할 수 있다.우선 top를 실행하면 이해하기 쉽다.

top -d1

top - 22:57:50 up  1:01,  2 users,  load average: 1.12, 1.10, 1.11
Tasks: 354 total,   1 running, 353 sleeping,   0 stopped,   0 zombie
%Cpu(s):  9.9 us,  8.4 sy,  0.0 ni, 81.5 id,  0.0 wa,  0.0 hi,  0.1 si,  0.0 st
KiB Mem : 16266584 total, 14474140 free,   625108 used,  1167336 buff/cache
KiB Swap:  2101244 total,  2101244 free,        0 used. 14733996 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 5573 appuser   20   0 3800348 896120 664472 S 101.0  5.5  55:24.00 <TARGET>
 6854 root      20   0  162144   2508   1596 R   0.7  0.0   0:07.21 top
 6727 root      20   0  159228   6160   4788 S   0.3  0.0   0:00.81 sshd

다행히도 의심스러운 과정 (%CPU가 101.0인 PID5573의 과정) 은 하나밖에 없었다.이 서버는 여러 코어를 탑재하고 있기 때문에 100% CPU를 사용하지만 전체적으로 80% 가까이 IDLE 상태임을 알 수 있습니다.그리고wa(IO권중)는 0.0이기 때문에 디스크 IO의 자원 경쟁이 발생하지 않는다는 것을 알 수 있다.사용자 공간(us)인지 내부 공간(sy)인지 전체 시스템에서 둥글기 때문에 어느 과정인지 알 수 없다(다른 과정은 성실하기 때문에 어느 정도에 의심 과정의 상황을 반영했다고 생각할 수 있다).prtstat과pidstat에서 개별 과정의 자원 이용 상황을 깊이 있게 조사한다.
※ 의심되는 프로세스의 프로세스 ID는 다음과 같습니다$PID(명령 입력).

prtstat $PID

Process: <TARGET>                State: S (sleeping)
  CPU#:  1              TTY: 0:0        Threads: 43
Process, Group and Session IDs
  Process ID: 5573                Parent ID: 5571
    Group ID: 5573               Session ID: 4393
  T Group ID: -1

Page Faults
  This Process    (minor major):   187723        21
  Child Processes (minor major):        0         0
CPU Times
  This Process    (user system guest blkio): 3107.80 2756.89   0.00   0.11
  Child processes (user system guest):         0.00   0.00   0.00
Memory
  Vsize:       3891 MB
  RSS:         917 MB                    RSS Limit: 18446744073709 MB
  Code Start:  0x400000                  Code Stop:  0x45a40c
  Stack Start: 0x7ffc0d830f70
  Stack Pointer (ESP): 0x7ffc0d830bb0    Inst Pointer (EIP): 0x7f5bdfb04f47
Scheduling
  Policy: normal
  Nice:   0              RT Priority: 0 (non RT)

CPU 타임즈의 항목에서 다시 한 번 확인할 수 있듯이 사용자 공간(user)이 조금 많고, 내부 공간(시스템)도 비교적 많은 CPU 시간을 사용하며, 디스크 IO(blkio)가 거의 없다.

# -u: CPU使用率を出力
# -I: CPUコアごとに出力
# 1 5: 1秒間隔5回
pidstat -p $PID -u -I 1 5

Linux 3.10.0-957.el7.x86_64 (db1)       2019年06月07日  _x86_64_        (3 CPU)

23時07分54秒   UID       PID    %usr %system  %guest    %CPU   CPU  Command
23時07分55秒  2000      5573   51.92   48.08    0.00   41.60     1  <TARGET>
23時07分56秒  2000      5573   58.00   44.00    0.00   43.22     1  <TARGET>
23時07分57秒  2000      5573   54.90   46.08    0.00   42.56     1  <TARGET>
23時07分58秒  2000      5573   51.49   48.51    0.00   42.44     1  <TARGET>
23時07分59秒  2000      5573   55.34   45.63    0.00   43.33     1  <TARGET>
平均値:   2000      5573   54.31   46.47    0.00   42.62     -  <TARGET>

pidstat 신기한 정보도 없다.CPU 3개가 장착되어 거의 CPU #1(시종 샘플링의 1초 5회 사이)을 차지합니다.
또한 수여-t 옵션을 통해 어느 라인이 시끄러운지 확인할 수 있다.

pidstat -p $PID -u -I -t 1 1

발췌하다

23時08分01秒   UID      TGID       TID    %usr %system  %guest    %CPU   CPU  Command
23時08分02秒  2000      5573         -   59.22   41.75    0.00   42.28     1  <TARGET>
23時08分02秒  2000         -      5573    0.00    0.00    0.00    0.00     1  |__<TARGET>
23時08分02秒  2000         -      5575    0.00    0.00    0.00    0.00     0  |__<TARGET>
23時08分02秒  2000         -      6125   59.22   40.78    0.00   41.87     1  |__<TARGET>
23時08分02秒  2000         -      6563    0.00    0.00    0.00    0.00     0  |__<TARGET>

우리는 스레드 #6125(TID)가 잘 작동하는 것을 발견했다.
또한 설치되지 않은 경우 pidstat 를 사용할 수 있습니다 ("-L"옵션이 있는 경우 스레드 정보를 얻을 수 있습니다).

ps -p $PID -Lf

발췌하다

UID        PID  PPID   LWP  C NLWP STIME TTY          TIME CMD
appuser   5573  5571  6123  0   43  6月07 ?      00:00:00 <TARGET>
appuser   5573  5571  6125 99   43  6月07 ?      02:07:51 <TARGET>
appuser   5573  5571  6127  0   43  6月07 ?      00:00:00 <TARGET>

C 열은 CPU 사용률입니다.NLWP(Number of Light Weight Process)는 스레드 수입니다.LWP는 스레드 ID입니다.
이렇게 하면 어느 CPU에서 작업할지 모르기 때문에 필요하다면, 예를 들어 다음과 같은 맞춤형 출력 (그리고 여분의 항목도 출력해 보십시오.)

# -L: スレッド情報出力
# -o: 出力項目指示
#   tid: thread id, c: CPU使用率, sgi_p: どのCPUか
#   cls: スケジューラクラス, ni: NICE値, pri: スケジューラプライオリティ, rtprio: リアルタイムスケジューラのプライオリティ
ps -p $PID -L -otid,c,sgi_p,cls,ni,pri,rtprio

  TID  C P CLS  NI PRI RTPRIO
 6123  0 *  TS   0  19      -
 6125 99 1  TS   0  19      -
 6127  0 *  TS   0  19      -

ps, 이 순간(즉, ps 명령이 샘플링을 할 때), 이 과정이나 라인이 어느 CPU에서 이동하는지 표시할 수 있다.CLS는 CPU 스케줄러에서 TS(기본 TimeSharing)로 동작합니다.
한 마디로 하면 지금까지 특정 과정의 특정 라인이 거의 하나의 CPU를 차지하고 동작을 하는 것을 발견했고 사용자 공간과 내부 핵 공간은 6:4 정도의 비율이다.
이어서 우리는 이 시끄러운 라인이 도대체 CPU 시간을 무엇에 썼는지 탐색할 것이다.

이 프로세스 라인은 구체적으로 무엇을 하고 있습니까?

sgi_p를 사용하여 실행 중인 과정이 무엇을 하는지 조사할 수 있지만 방해성이 높기 때문에 사용 시 주의해야 한다.어떤 경우, 이 방해는 이 사건이 더 이상 발생하지 않거나 다른 문제가 발생할 수 있다.
따라서 시스템 호출을 몇 번이나 실행했는지 계수strace, perf, (시스템탭), stap 등 관측 도구를 편리하게 사용할 수 있다.
그러나 dtrace과stap는 반드시 스스로 스크립트를 써야 하기 때문에 어느 정도 유형에 맞는 조사를 위해 dtrace 사용하기 쉽고 사용 방법에 따라 상당히 깊은 통찰을 얻을 수 있다.
이번에는 대상 과정을 알았기 때문에 그 과정만을 대상으로 다양한 조사를 진행했다.

# stat: 基本統計を出力
# -p: 指定したPIDのプロセスを対象（システム全体を対象とする場合は"-a"指定）
# -d: 詳細情報出力
perf stat -p $PID -d sleep 1

이렇게 집행perf 과정에서 1초의 통계를 낸다.

 Performance counter stats for process id '5573':

       1006.984534      task-clock (msec)         #    0.998 CPUs utilized
               121      context-switches          #    0.120 K/sec
                 4      cpu-migrations            #    0.004 K/sec
                 5      page-faults               #    0.005 K/sec
   <not supported>      cycles
   <not supported>      instructions
   <not supported>      branches
   <not supported>      branch-misses
   <not supported>      L1-dcache-loads
   <not supported>      L1-dcache-load-misses
   <not supported>      LLC-loads
   <not supported>      LLC-load-misses

       1.009087391 seconds time elapsed

유감스럽게도 이 환경에서는 CPU 주기, 명령어, 분기 수 등 상세한 CPU 통계를 얻을 수 없습니다(가상 환경에서는 쉽습니다).
여기서 알 수 있듯이 약 1초 동안 CPU를 거의 사용했고context-switch(위아래 문장 전환, 즉 사용자 공간과 내부 핵 공간 전환을 실행)는 그렇게 빈번하지 않았다(신기한 정보는 없었다).
다음은 sleep 1 대신 어떤 시스템 호출이 실행되고 있는지 조사한다.

# -e: カウントするイベントを指定（ワイルドカード可）
#   指定可能なイベントのリストは`perf list`で確認できる
perf stat -p $PID -e 'syscalls:*' sleep 1

발췌하다

                 0      syscalls:sys_exit_getcwd
           454,232      syscalls:sys_enter_select
           454,246      syscalls:sys_exit_select
                 0      syscalls:sys_enter_pselect6
            ...
                 0      syscalls:sys_exit_setns
                91      syscalls:sys_enter_nanosleep
                90      syscalls:sys_exit_nanosleep
                 0      syscalls:sys_enter_timer_create

초당 starce 시스템 호출이 40만 건을 넘어섰습니다.구체적인 호출 부분이 어떤지 다시 한 번 조사해 봅시다.

perf top -p $PID

Zoom-in이면 어셈블리 코드도 나타납니다.

아는 사람은 보면 알겠지만 이제 용서해 주세요.
참고로 select 이라면 개요 레벨 출력입니다.

한 마디로 하면 지금까지 데이터 복제를 담당한 라인은 CPU가 높아진 범인이었다(그림에서는 모호하지만 이름에서 알 수 있듯이 복제 라인이었다).초당 수십만 회perf top -p $PID --sort comm,dso의 호출 횟수를 보면 코드 오류(부적절한 순환)일 수도 있다.이런 메시지를 만든 사람에게 전달해 WHY의 일을 명확히 하고 해결하도록 해야 한다.
참고로 select 보통 시간 초과는 100000으로 지정됩니다.μs, 즉 100ms, 최대 초간 10회만 실행되며, 이 사건 발생 시strace -f -e trace=select -p $PID는 0이 아닌 0으로 되돌아갔지만 주 처리가 아닌 다시 select로 되돌아갔다.