【Cassandra】Cassandra自体のスレッドの状況確認用コマンドのメモ

## 0. はじめに

・Cassandra自体のスレッドの状況確認用コマンドのメモ
・例の環境はCentOS Linux release 7.6

## 1. nodetool tpstats

・Cassabdraのスレッドプール使用状況の統計情報を表示
・プール名とタスクは、datastaxさんの管理者ガイドとか参照がよさそう
　https://docs.datastax.com/ja/dse/5.1/dse-admin/datastax_enterprise/tools/nodetool/toolsTPstats.html
・Completed,Blocked,All time blockedのカウンタ値はどんどん加算されてくみたいなので、差分をとっていけば
　カウンタ値はノードのCassandra起動時にリセット
・プールの品揃えはCassandraのバージョンによって違うので注意

```
# nodetool tpstats
Pool Name                    Active   Pending      Completed   Blocked  All time blocked
MutationStage                     0         1         570502         0                 0
ReadStage                         0         1          87775         0                 0
RequestResponseStage              0         0         608465         0                 0
ReadRepairStage                   0         0           9062         0                 0
CounterMutationStage              0         0              0         0                 0
MiscStage                         0         0              0         0                 0
HintedHandoff                     0         0             24         0                 0
GossipStage                       0         0          54747         0                 0
CacheCleanupExecutor              0         0              0         0                 0
InternalResponseStage             0         0              0         0                 0
CommitLogArchiver                 0         0              0         0                 0
ValidationExecutor                0         0              0         0                 0
MigrationStage                    0         0              0         0                 0
CompactionExecutor                0         0           7617         0                 0
AntiEntropyStage                  0         0              0         0                 0
PendingRangeCalculator            0         0              2         0                 0
Sampler                           0         0              0         0                 0
MemtableFlushWriter               0         0             31         0                 0
MemtablePostFlush                 0         0            280         0                 0
MemtableReclaimMemory             0         0             31         0                 0
Native-Transport-Requests        16        12         251174         0               813

Message type           Dropped
READ                         0
RANGE_SLICE                  0
_TRACE                       0
MUTATION                     0
COUNTER_MUTATION             0
BINARY                       0
REQUEST_RESPONSE             0
PAGED_RANGE                  0
READ_REPAIR                  0
# nodetool tpstats
Pool Name                    Active   Pending      Completed   Blocked  All time blocked
MutationStage                     0         1         588808         0                 0
ReadStage                         0         1          91641         0                 0
RequestResponseStage              0       110         634625         0                 0
ReadRepairStage                   0         0           9459         0                 0
CounterMutationStage              0         0              0         0                 0
MiscStage                         0         0              0         0                 0
HintedHandoff                     0         0             24         0                 0
GossipStage                       0         0          54821         0                 0
CacheCleanupExecutor              0         0              0         0                 0
InternalResponseStage             0         0              0         0                 0
CommitLogArchiver                 0         0              0         0                 0
ValidationExecutor                0         0              0         0                 0
MigrationStage                    0         0              0         0                 0
CompactionExecutor                0         0           7650         0                 0
AntiEntropyStage                  0         0              0         0                 0
PendingRangeCalculator            0         0              2         0                 0
Sampler                           0         0              0         0                 0
MemtableFlushWriter               0         0             31         0                 0
MemtablePostFlush                 0         0            280         0                 0
MemtableReclaimMemory             0         0             31         0                 0
Native-Transport-Requests         0         0         260023         0               813

Message type           Dropped
READ                         0
RANGE_SLICE                  0
_TRACE                       0
MUTATION                     0
COUNTER_MUTATION             0
BINARY                       0
REQUEST_RESPONSE             0
PAGED_RANGE                  0
READ_REPAIR                  0
# 
```

## 2. ps

・OSの基本のpsコマンド 
・実行ユーザとかコマンド文字列でCassandraプロセスを判別する。例は、DSEのディストリビューションなので、dseでgrepしてる
・-L指定でスレッドをわらわら表示、重いのがいるとか、スレッド数がどれくらいかはわかりそう。

```
# ps aux
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.0  0.0 128268  6956 ?        Ss   18:09   0:01 /usr/lib/systemd/systemd --switched-root --system --deserialize 22
　:
　略
　:
cass_tkv  4601  2.5 29.9 4083312 2399260 ?     Sl   18:10   3:56 /bin/java -Ddse.server_process - ...t
　:
　略
　:

# ps aux -L --lines 1 --cols 100 | grep dse | grep -v grep
cass_tkv  4601  4601  0.0  168 29.6 4083296 2373676 ?     Sl   18:10   0:00 /bin/java -Ddse.server_p
cass_tkv  4601  4768  0.2  168 29.6 4083296 2373676 ?     Sl   18:10   0:09 /bin/java -Ddse.server_p
cass_tkv  4601  4769  0.0  168 29.6 4083296 2373676 ?     Sl   18:10   0:01 /bin/java -Ddse.server_p
cass_tkv  4601  4770  0.1  168 29.6 4083296 2373676 ?     Sl   18:10   0:04 /bin/java -Ddse.server_p
cass_tkv  4601  4771  0.0  168 29.6 4083296 2373676 ?     Sl   18:10   0:00 /bin/java -Ddse.server_p
cass_tkv  4601  4772  0.0  168 29.6 4083296 2373676 ?     Sl   18:10   0:00 /bin/java -Ddse.server_p
cass_tkv  4601  4773  0.0  168 29.6 4083296 2373676 ?     Sl   18:10   0:00 /bin/java -Ddse.server_p
　:
#

# ps aux -L | grep dse | grep -v grep | wc -l
169
#
 
```

## 3. nodetool sjk ttop

・CassandraのJavaプロセスのどのスレッドがどのくらいCPUとかメモリとか使ってるかは、nodetool sjk ttopで確認できる。
・どのスレッドが何の役割かっていう説明資料はみあたらないので、自分で調べないといけない...。

### ① CPU使用率順表示 ( デフォルト )

・デフォルトはCPU使用率順
・-nは表示スレッド数の上限を指定
・other: cpu=っていうのは、GCとか、そういうのだと思われ。

```
# nodetool sjk ttop -n 100 
Monitoring threads ...

2019-11-16T19:17:09.973+0900 Process summary 
  process cpu=3.18%
  application cpu=2.67% (user=1.68% sys=0.98%)
  other: cpu=0.51% 
  thread count: 161
  heap allocation rate 1593kb/s
[000337] user= 1.12% sys= 0.35% alloc= 1271kb/s - RMI TCP Connection(67)-127.0.0.1
[000121] user= 0.00% sys= 0.41% alloc=   15kb/s - MessagingService-Outgoing-/10.0.2.123
[000014] user= 0.19% sys=-0.03% alloc=  1046b/s - metrics-meter-tick-thread-1
[000135] user= 0.00% sys= 0.12% alloc=   15kb/s - Thread-4
[000016] user= 0.00% sys= 0.08% alloc=   67kb/s - ScheduledTasks:1
[000130] user= 0.19% sys=-0.11% alloc=  182kb/s - pool-13-thread-1
　:

```

### ② スレッド名順表示 -o NAME

・スレッド名順でソートすると、どの種類のスレッドがいくつとか数えやすい

```
# nodetool sjk ttop -n 100 -o NAME
Monitoring threads ...

2019-11-16T19:14:15.948+0900 Process summary 
  process cpu=3.07%
  application cpu=2.73% (user=1.43% sys=1.29%)
  other: cpu=0.35% 
  thread count: 159
  heap allocation rate 1590kb/s
[000113] user= 0.00% sys= 0.00% alloc=     0b/s - ACCEPT-/10.0.2.121
[000075] user= 0.00% sys= 0.00% alloc=     0b/s - AntiEntropyStage:1
[000018] user= 0.00% sys= 0.02% alloc=  2065b/s - Background_Reporter:1
[000117] user= 0.00% sys= 0.00% alloc=     0b/s - BatchlogTasks:1
[000028] user= 0.00% sys= 0.00% alloc=     0b/s - COMMIT-LOG-ALLOCATOR
[000027] user= 0.00% sys= 0.00% alloc=     0b/s - CommitLogArchiver:1
  :
```

### ③ スレッド名のワイルドカード指定

・Compaction Executor指定で監視する場合の例

```
# nodetool sjk ttop -n 100 -f 'Compaction*'
Monitoring threads ...

2019-11-16T18:39:48.349+0900 Process summary 
  process cpu=3.17%
  application cpu=2.94% (user=2.05% sys=0.88%)
  other: cpu=0.24% 
  thread count: 2
  heap allocation rate 1803kb/s
[000163] user= 0.19% sys= 0.01% alloc=   99kb/s - CompactionExecutor:3
[000164] user= 0.19% sys=-0.03% alloc=   83kb/s - CompactionExecutor:4




2019-11-16T18:39:58.305+0900 Process summary 
  process cpu=2.91%
  application cpu=2.73% (user=1.61% sys=1.12%)
  other: cpu=0.18% 
  thread count: 2
  heap allocation rate 1577kb/s
[000163] user= 0.00% sys= 0.00% alloc=     0b/s - CompactionExecutor:3
[000164] user= 0.00% sys= 0.00% alloc=     0b/s - CompactionExecutor:4

```

## 4. strace

・挙動がよくわからなくて、困ったときの必殺技 strace ...

### ① とりあえずstrace

・Javaマルチスレッドなので-f指定は必須、情報量が多すぎて、あまり実用的ではない。

```
# strace -t -f -p 4601 
strace: Process 4601 attached with 168 threads
[pid 14364] 21:00:21 restart_syscall(<... resuming interrupted futex ...> <unfinished ...>
[pid 13446] 21:00:21 restart_syscall(<... resuming interrupted futex ...> <unfinished ...>
[pid 12961] 21:00:21 restart_syscall(<... resuming interrupted futex ...> <unfinished ...>
[pid  8316] 21:00:21 futex(0x7ff28c1ed4b4, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
[pid  8315] 21:00:21 futex(0x16ab224, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
[pid  8314] 21:00:21 futex(0x13bb024, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
　:
```

### ② ファイルI/Oの確認

・ファイルI/O関連に絞って確認する例  -e trace=file

```
# strace -t -y -f -p 4601 -e trace=file

strace: Process 4601 attached with 283 threads
[pid  4899] 21:26:54 stat("/var/log/cassandra/system.log", {st_mode=S_IFREG|0644, st_size=56683525, ...}) = 0
[pid  4893] 21:26:56 stat("/var/log/cassandra/system.log", {st_mode=S_IFREG|0644, st_size=56683666, ...}) = 0
[pid  4904] 21:26:56 stat("/var/log/cassandra/system.log", {st_mode=S_IFREG|0644, st_size=56684005, ...}) = 0
[pid  4904] 21:26:56 stat("/var/log/cassandra/system.log", {st_mode=S_IFREG|0644, st_size=56684401, ...}) = 0
[pid  4904] 21:26:56 stat("/var/log/cassandra/system.log", {st_mode=S_IFREG|0644, st_size=56684851, ...}) = 0
[pid  4788] 21:26:57 stat("/usr/share/dse-4.8.16/cassandra-topology.properties", 0x7ff280786950) = -1 ENOENT (No such file or directory)
[pid  4788] 21:26:57 stat("/usr/share/dse-4.8.16/resources/dse/conf/cassandra-topology.properties", 0x7ff280786950) = -1 ENOENT (No such file or directory)
[pid  4788] 21:26:57 stat("/usr/share/dse-4.8.16/resources/cassandra/conf/cassandra-topology.properties", {st_mode=S_IFREG|0644, st_size=1358, ...}) = 0
[pid  4788] 21:26:57 stat("/usr/share/dse-4.8.16/resources/cassandra/conf/cassandra-topology.properties", {st_mode=S_IFREG|0644, st_size=1358, ...}) = 0
　:

[pid  4851] 21:27:40 lstat("/data", {st_mode=S_IFDIR|0755, st_size=23, ...}) = 0
[pid  4851] 21:27:40 lstat("/data/cassandra", {st_mode=S_IFDIR|0755, st_size=82, ...}) = 0
[pid  4851] 21:27:40 lstat("/data/cassandra/data", {st_mode=S_IFDIR|0777, st_size=166, ...}) = 0
[pid  4851] 21:27:40 lstat("/data/cassandra/data/stest01", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  4851] 21:27:40 lstat("/data/cassandra/data/stest01/test01-62764911028011ea82cf4d26f3ae4649", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  4851] 21:27:40 lstat("/data/cassandra/data/stest01/test01-62764911028011ea82cf4d26f3ae4649/stest01-test01-ka-102-Data.db", {st_mode=S_IFREG|0644, st_size=72822904, ...}) = 0
[pid  4851] 21:27:40 open("/data/cassandra/data/stest01/test01-62764911028011ea82cf4d26f3ae4649/stest01-test01-ka-102-Data.db", O_RDONLY) = 443</data/cassandra/data/stest01/test01-62764911028011ea82cf4d26f3ae4649/stest01-test01-ka-102-Data.db>
　:

```

・I/Oの中身の確認例...、実用的かどうかはわからないけど
　/proc/pid/fd下から目的のファイルのファイル記述子を確認して、-e writeとか -e readを仕掛ける

```

# ls -l /proc/4601/fd/* | grep system.log
l-wx------. 1 cass_tkv cass_tkv 64 11月 16 20:32 /proc/4601/fd/424 -> /var/log/cassandra/system.log
# 

# strace -t -y -f -p 4601 -e write=424
　:
[pid  4904] 21:41:29 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid  4904] 21:41:29 futex(0x7ff2a9de8da8, FUTEX_WAKE_PRIVATE, 1) = 0
[pid  4904] 21:41:29 stat("/var/log/cassandra/system.log", {st_mode=S_IFREG|0644, st_size=82322526, ...}) = 0
[pid  4904] 21:41:29 write(424</var/log/cassandra/system.log>, "DEBUG [pool-13-thread-1] 2019-11"..., 101) = 101
 | 00000  44 45 42 55 47 20 5b 70  6f 6f 6c 2d 31 33 2d 74  DEBUG [pool-13-t |
 | 00010  68 72 65 61 64 2d 31 5d  20 32 30 31 39 2d 31 31  hread-1] 2019-11 |
 | 00020  2d 31 36 20 32 31 3a 34  31 3a 32 39 2c 38 32 39  -16 21:41:29,829 |
 | 00030  20 20 44 73 65 55 74 69  6c 2e 6a 61 76 61 3a 32    DseUtil.java:2 |
 | 00040  30 35 20 2d 20 44 79 6e  61 6d 69 63 45 6e 64 70  05 - DynamicEndp |
 | 00050  6f 69 6e 74 53 6e 69 74  63 68 20 64 65 74 65 63  ointSnitch detec |
 | 00060  74 65 64 2e 0a                                    ted..            |
[pid  4904] 21:41:29 write(1<socket:[37530]>, "DEBUG 21:41:29,829  DynamicEndpo"..., 52) = 52
[pid  4904] 21:41:29 write(424</var/log/cassandra/system.log>, "DEBUG [pool-13-thread-1] 2019-11"..., 97) = 97
 | 00000  44 45 42 55 47 20 5b 70  6f 6f 6c 2d 31 33 2d 74  DEBUG [pool-13-t |
 | 00010  68 72 65 61 64 2d 31 5d  20 32 30 31 39 2d 31 31  hread-1] 2019-11 |
 | 00020  2d 31 36 20 32 31 3a 34  31 3a 32 39 2c 38 33 30  -16 21:41:29,830 |
 | 00030  20 20 44 73 65 55 74 69  6c 2e 6a 61 76 61 3a 32    DseUtil.java:2 |
 | 00040  30 38 20 2d 20 44 73 65  44 65 6c 65 67 61 74 65  08 - DseDelegate |
 | 00050  53 6e 69 74 63 68 20 64  65 74 65 63 74 65 64 2e  Snitch detected. |
 | 00060  0a                                                .                |
[pid  4893] 21:41:29 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
　:
```