Hatena::ブログ(Diary)

ablog このページをアンテナに追加 RSSフィード

2018-05-17

MongoDB に YCSB でベンチマークをかけてみる

インストール

MongoDB
$ sudo vi /etc/yum.repos.d/mongodb.repo
[mongodb]
name=MongoDB repo
baseurl=http://downloads-distro.mongodb.org/repo/redhat/os/x86_64/
gpgcheck=0
enabled=1
$ sudo yum -y install git mongodb-org
JDK 1.8
$ sudo yum -y install java-1.8.0-openjdk-devel
$ sudo update-alternatives --config java

There are 2 programs which provide 'java'.

  Selection    Command
-----------------------------------------------
*+ 1           /usr/lib/jvm/jre-1.7.0-openjdk.x86_64/bin/java
   2           /usr/lib/jvm/jre-1.8.0-openjdk.x86_64/bin/java

Enter to keep the current selection[+], or type selection number: 2
Maven
$ cd /usr/local/lib/
$ sudo wget http://ftp.riken.jp/net/apache/maven/maven-3/3.5.3/binaries/apache-maven-3.5.3-bin.tar.gz
$ sudo tar xfvz apache-maven-3.5.3-bin.tar.gz
$ sudo ln -s apache-maven-3.5.3/ maven
  • ~/.bash_profile に以下を追記する
MAVEN_HOME=/usr/local/lib/maven
export PATH=$PATH:$MAVEN_HOME/bin
  • ~/.bash_profile を読み込む
$ . ~/.bash_profile
YCSB
$ cd
$ git clone https://github.com/brianfrankcooper/YCSB.git 
$ mvn clean package

準備

$ sudo service mongod start
  • ~/YCSB/workload/workloada を以下の通り編集
#recordcount=1000
recordcount=1000000
#operationcount=1000
operationcount=1000000
  • データをロードする
$ ./bin/ycsb load mongodb -P workloads/workloada >> ycsb-load.log

ベンチマーク実行

$ ./bin/ycsb run mongodb -threads 5 -P workloads/workloada >> ycsb-run.log

結果

サマリ
  • AverageLatency(us)
項目5スレッド10スレッド50スレッド100スレッド200スレッド
READ1052795987084121
CLEANUP67548115711665
UPDATE152312286960879450
  • mongostat の接続数(conn)とキュー数(qr)
    • conn: The total number of open connections.
    • qr: The length of the queue of clients waiting to read data from the MongoDB instance.
項目5スレッド10スレッド50スレッド100スレッド200スレッド
conn0-33-847-48102102
qr712529998

5スレッド
  • 実行結果
$ ./bin/ycsb run mongodb -threads 5 -P workloads/workloada
(中略)
[OVERALL], RunTime(ms), 26441
[OVERALL], Throughput(ops/sec), 37820.052191672024
[TOTAL_GCS_PS_Scavenge], Count, 211
[TOTAL_GC_TIME_PS_Scavenge], Time(ms), 163
[TOTAL_GC_TIME_%_PS_Scavenge], Time(%), 0.616466850724254
[TOTAL_GCS_PS_MarkSweep], Count, 0
[TOTAL_GC_TIME_PS_MarkSweep], Time(ms), 0
[TOTAL_GC_TIME_%_PS_MarkSweep], Time(%), 0.0
[TOTAL_GCs], Count, 211
[TOTAL_GC_TIME], Time(ms), 163
[TOTAL_GC_TIME_%], Time(%), 0.616466850724254
[READ], Operations, 499550
[READ], AverageLatency(us), 105.58547292563307
[READ], MinLatency(us), 36
[READ], MaxLatency(us), 52735
[READ], 95thPercentileLatency(us), 214
[READ], 99thPercentileLatency(us), 306
[READ], Return=OK, 499550
(中略)
[CLEANUP], Operations, 5
[CLEANUP], AverageLatency(us), 675.8
[CLEANUP], MinLatency(us), 1
[CLEANUP], MaxLatency(us), 3369
[CLEANUP], 95thPercentileLatency(us), 3369
[CLEANUP], 99thPercentileLatency(us), 3369
[CLEANUP], 1, 3.0
[CLEANUP], 7, 1.0
[CLEANUP], 3369, 1.0
[UPDATE], Operations, 500450
[UPDATE], AverageLatency(us), 152.94304725746827
[UPDATE], MinLatency(us), 56
[UPDATE], MaxLatency(us), 52735
[UPDATE], 95thPercentileLatency(us), 176
[UPDATE], 99thPercentileLatency(us), 242
[UPDATE], Return=OK, 500450
  • mongostat
$ mongostat 5
connected to: 127.0.0.1
insert  query update delete getmore command flushes mapped  vsize    res faults  locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
     *0     *0     *0     *0       0     0|0       0  4.03g  8.38g  2.02g      0  ycsb:0.0%          0       0|0     0|0    12b   635b     1   17:38:25
    *0  13106  13080     *0       0     4|0       0  4.03g  8.38g  3.07g      0 ycsb:29.1%          0       0|0     0|5     4m    16m     7   17:38:30
    *0  19245  19289     *0       0     0|0       0  4.03g  8.38g  3.29g      0 ycsb:40.3%          0       0|0     0|5     7m    24m     7   17:38:35
    *0  19340  19428     *0       0     0|0       0  4.03g  8.38g  3.25g      0 ycsb:40.2%          0       3|0     0|1     7m    24m     7   17:38:40
    *0  19533  19365     *0       0     0|0       0  4.03g  8.38g  2.13g      0 ycsb:40.8%          0       4|0     0|1     7m    24m     7   17:38:45
    *0  19203  19476     *0       0     0|0       0  4.03g  8.38g  2.57g      0 ycsb:40.5%          0       1|0     4|0     7m    24m     7   17:38:50
    *0   9481   9448     *0       0     0|0       0  4.03g  8.38g  2.02g      0 ycsb:19.7%          0       0|0     0|0     3m    12m     1   17:38:55
10スレッド
  • 実行結果
$ ./bin/ycsb run mongodb -threads 10 -P workloads/workloada
(中略)
[OVERALL], RunTime(ms), 30006
[OVERALL], Throughput(ops/sec), 33326.667999733385
[TOTAL_GCS_PS_Scavenge], Count, 214
[TOTAL_GC_TIME_PS_Scavenge], Time(ms), 180
[TOTAL_GC_TIME_%_PS_Scavenge], Time(%), 0.599880023995201
[TOTAL_GCS_PS_MarkSweep], Count, 0
[TOTAL_GC_TIME_PS_MarkSweep], Time(ms), 0
[TOTAL_GC_TIME_%_PS_MarkSweep], Time(%), 0.0
[TOTAL_GCs], Count, 214
[TOTAL_GC_TIME], Time(ms), 180
[TOTAL_GC_TIME_%], Time(%), 0.599880023995201
[READ], Operations, 499879
[READ], AverageLatency(us), 279.0026706462964
[READ], MinLatency(us), 36
[READ], MaxLatency(us), 58719
[READ], 95thPercentileLatency(us), 670
[READ], 99thPercentileLatency(us), 973
[READ], Return=OK, 499879
(中略)
[CLEANUP], Operations, 10
[CLEANUP], AverageLatency(us), 481.7
[CLEANUP], MinLatency(us), 0
[CLEANUP], MaxLatency(us), 4807
[CLEANUP], 95thPercentileLatency(us), 4807
[CLEANUP], 99thPercentileLatency(us), 4807
[CLEANUP], 0, 3.0
[CLEANUP], 1, 5.0
[CLEANUP], 6, 1.0
[CLEANUP], 4807, 1.0
[UPDATE], Operations, 500121
[UPDATE], AverageLatency(us), 312.47620275893235
[UPDATE], MinLatency(us), 58
[UPDATE], MaxLatency(us), 58623
[UPDATE], 95thPercentileLatency(us), 384
[UPDATE], 99thPercentileLatency(us), 597
[UPDATE], Return=OK, 500121
  • mongostat
$ mongostat 5
    *0     *0     *0     *0       0     0|0       0  4.03g  8.38g  2.02g      0  ycsb:0.0%          0       0|0     0|0    12b   635b     1   17:45:52
    *0   1929   1904     *0       0     7|0       0  4.03g  8.38g  2.76g      0  ycsb:5.8%          0       6|0     0|1   720k     2m    12   17:45:57
    *0  19215  19298     *0       0     0|0       0  4.03g  8.38g  2.78g      0 ycsb:47.1%          0       3|0     2|0     7m    24m    12   17:46:02
    *0  17083  17092     *0       0     0|0       0  4.03g  8.38g  3.09g      0 ycsb:42.9%          0       7|0     0|1     6m    21m    12   17:46:07
    *0  16112  16202     *0       0     0|0       0  4.03g  8.38g  2.63g      0 ycsb:41.4%          0       7|0     0|1     6m    20m    12   17:46:12
    *0  16150  16125     *0       0     0|0       0  4.03g  8.38g  2.73g      0 ycsb:41.3%          0       6|0     1|0     6m    20m    12   17:46:17
    *0  16327  16227     *0       0     0|0       0  4.03g  8.38g  3.16g      0 ycsb:40.5%          0       8|0     0|1     6m    20m    12   17:46:22
    *0  13158  13174     *0       0     0|0       0  4.03g  8.38g  2.52g      0 ycsb:33.9%          0       0|0     0|0     4m    16m     1   17:46:27
50スレッド
  • 実行結果
$ ./bin/ycsb run mongodb -threads 50 -P workloads/workloada
(中略)
[OVERALL], RunTime(ms), 35126
[OVERALL], Throughput(ops/sec), 28468.94038603883
[TOTAL_GCS_PS_Scavenge], Count, 44
[TOTAL_GC_TIME_PS_Scavenge], Time(ms), 71
[TOTAL_GC_TIME_%_PS_Scavenge], Time(%), 0.2021294767408757
[TOTAL_GCS_PS_MarkSweep], Count, 0
[TOTAL_GC_TIME_PS_MarkSweep], Time(ms), 0
[TOTAL_GC_TIME_%_PS_MarkSweep], Time(%), 0.0
[TOTAL_GCs], Count, 44
[TOTAL_GC_TIME], Time(ms), 71
[TOTAL_GC_TIME_%], Time(%), 0.2021294767408757
[READ], Operations, 499284
[READ], AverageLatency(us), 598.3327685245271
[READ], MinLatency(us), 36
[READ], MaxLatency(us), 91775
[READ], 95thPercentileLatency(us), 1805
[READ], 99thPercentileLatency(us), 3273
[READ], Return=OK, 499284
(中略)
[CLEANUP], Operations, 50
[CLEANUP], AverageLatency(us), 157.74
[CLEANUP], MinLatency(us), 0
[CLEANUP], MaxLatency(us), 7863
[CLEANUP], 95thPercentileLatency(us), 2
[CLEANUP], 99thPercentileLatency(us), 7863
[CLEANUP], 0, 30.0
[CLEANUP], 1, 17.0
[CLEANUP], 2, 1.0
[CLEANUP], 6, 1.0
[CLEANUP], 7863, 1.0
[UPDATE], Operations, 500716
[UPDATE], AverageLatency(us), 2869.2255490138123
[UPDATE], MinLatency(us), 56
[UPDATE], MaxLatency(us), 103935
[UPDATE], 95thPercentileLatency(us), 6539
[UPDATE], 99thPercentileLatency(us), 17967
[UPDATE], Return=OK, 500716
  • mongostat
$ mongostat 5
connected to: 127.0.0.1
insert  query update delete getmore command flushes mapped  vsize    res faults  locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
    *0     *0     *0     *0       0     0|0       0  4.03g  8.38g  2.02g      0  ycsb:0.0%          0       0|0     0|0    12b   635b     1   17:49:02
    *0   3960   3963     *0       0    31|0       0  4.03g  8.39g  2.68g      0 ycsb:12.4%          0      48|0     0|1     1m     5m    52   17:49:07
    *0  15027  15111     *0       0     0|0       0  4.03g  8.39g   3.2g      0 ycsb:38.6%          0      43|0     1|0     5m    19m    52   17:49:12
    *0  14852  14883     *0       0     0|0       0  4.03g  8.39g  2.95g      0 ycsb:38.6%          0      47|0     0|1     5m    18m    52   17:49:17
    *0  14897  14960     *0       0     0|0       0  4.03g  8.39g   2.6g      0 ycsb:38.7%          0      47|0     1|0     5m    18m    52   17:49:22
    *0  14114  14153     *0       0     0|0       0  4.03g  8.39g  2.94g      0 ycsb:37.4%          0       0|0    0|49     5m    17m    52   17:49:27
    *0  13728  13753     *0       0     0|0       0  4.03g  8.39g  2.88g      0 ycsb:36.6%          0      48|0     0|0     5m    17m    52   17:49:32
    *0  13769  13751     *0       0     0|0       0  4.03g  8.39g  3.04g      0 ycsb:36.4%          0      49|0     0|1     5m    17m    52   17:49:37
    *0   9507   9565     *0       0     0|0       0  4.03g  8.38g  2.02g      0 ycsb:25.9%          0       0|0     0|0     3m    12m     1   17:49:42
100スレッド
  • 実行結果
$ ./bin/ycsb run mongodb -threads 100 -P workloads/workloada
(中略)
[OVERALL], RunTime(ms), 34437
[OVERALL], Throughput(ops/sec), 29038.534134796875
[TOTAL_GCS_PS_Scavenge], Count, 45
[TOTAL_GC_TIME_PS_Scavenge], Time(ms), 86
[TOTAL_GC_TIME_%_PS_Scavenge], Time(%), 0.2497313935592531
[TOTAL_GCS_PS_MarkSweep], Count, 0
[TOTAL_GC_TIME_PS_MarkSweep], Time(ms), 0
[TOTAL_GC_TIME_%_PS_MarkSweep], Time(%), 0.0
[TOTAL_GCs], Count, 45
[TOTAL_GC_TIME], Time(ms), 86
[TOTAL_GC_TIME_%], Time(%), 0.2497313935592531
[READ], Operations, 499757
[READ], AverageLatency(us), 708.4381929617795
[READ], MinLatency(us), 33
[READ], MaxLatency(us), 140031
[READ], 95thPercentileLatency(us), 2329
[READ], 99thPercentileLatency(us), 4363
[READ], Return=OK, 499757
(中略)
[CLEANUP], Operations, 100
[CLEANUP], AverageLatency(us), 116.06
[CLEANUP], MinLatency(us), 0
[CLEANUP], MaxLatency(us), 11575
[CLEANUP], 95thPercentileLatency(us), 1
[CLEANUP], 99thPercentileLatency(us), 6
[CLEANUP], 0, 70.0
[CLEANUP], 1, 28.0
[CLEANUP], 6, 1.0
[CLEANUP], 11575, 1.0
[UPDATE], Operations, 500243
[UPDATE], AverageLatency(us), 6087.91907532939
[UPDATE], MinLatency(us), 52
[UPDATE], MaxLatency(us), 146815
[UPDATE], 95thPercentileLatency(us), 13855
[UPDATE], 99thPercentileLatency(us), 22255
[UPDATE], Return=OK, 500243
  • mongostat
$ mongostat 5
connected to: 127.0.0.1
insert  query update delete getmore command flushes mapped  vsize    res faults  locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
    *0     *0     *0     *0       0     0|0       0  4.03g  8.38g  2.02g      0  ycsb:0.0%          0       0|0     0|0    12b   635b     1   17:53:18
    *0   1742   1711     *0       0    61|0       0  4.03g  8.44g  2.41g      0  ycsb:6.0%          0      97|0     0|0   650k     2m   102   17:53:23
    *0  14664  14544     *0       0     0|0       0  4.03g  8.44g  3.04g      0 ycsb:39.0%          0      97|0     0|1     5m    18m   102   17:53:28
    *0  14603  14616     *0       0     0|0       0  4.03g  8.44g  2.83g      0 ycsb:37.9%          0       0|0   0|100     5m    18m   102   17:53:33
    *0  14826  14810     *0       0     0|0       0  4.03g  8.44g  2.36g      0 ycsb:37.9%          0      99|1     0|1     5m    18m   102   17:53:38
    *0  14792  14851     *0       0     0|0       0  4.03g  8.44g   2.9g      0 ycsb:38.4%          0      99|0     0|1     5m    18m   102   17:53:43
    *0  14713  14861     *0       0     0|0       0  4.03g  8.44g  2.57g      0 ycsb:38.5%          0      27|0    0|73     5m    18m   102   17:53:48
    *0  14712  14718     *0       0     0|0       0  4.03g  8.44g  2.95g      0 ycsb:37.6%          0      97|0     0|1     5m    18m   102   17:53:53
    *0   9896   9935     *0       0     0|0       0  4.03g  8.38g  2.02g      0 ycsb:26.3%          0       0|0     0|0     3m    12m     1   17:53:58
    *0     *0     *0     *0       0     0|0       0  4.03g  8.38g  2.02g      0  ycsb:0.0%          0       0|0     0|0    12b   635b     1   17:54:03
200スレッド
  • 実行結果
$ ./bin/ycsb run mongodb -threads 200 -P workloads/workloada
(中略)
[OVERALL], RunTime(ms), 34298
[OVERALL], Throughput(ops/sec), 29156.21902151729
[TOTAL_GCS_PS_Scavenge], Count, 45
[TOTAL_GC_TIME_PS_Scavenge], Time(ms), 87
[TOTAL_GC_TIME_%_PS_Scavenge], Time(%), 0.2536591054872004
[TOTAL_GCS_PS_MarkSweep], Count, 0
[TOTAL_GC_TIME_PS_MarkSweep], Time(ms), 0
[TOTAL_GC_TIME_%_PS_MarkSweep], Time(%), 0.0
[TOTAL_GCs], Count, 45
[TOTAL_GC_TIME], Time(ms), 87
[TOTAL_GC_TIME_%], Time(%), 0.2536591054872004
[READ], Operations, 500000
[READ], AverageLatency(us), 4121.626464
[READ], MinLatency(us), 36
[READ], MaxLatency(us), 145279
[READ], 95thPercentileLatency(us), 7095
[READ], 99thPercentileLatency(us), 10551
[READ], Return=OK, 500000
(中略)
[CLEANUP], Operations, 200
[CLEANUP], AverageLatency(us), 65.245
[CLEANUP], MinLatency(us), 0
[CLEANUP], MaxLatency(us), 13007
[CLEANUP], 95thPercentileLatency(us), 1
[CLEANUP], 99thPercentileLatency(us), 1
[CLEANUP], 0, 166.0
[CLEANUP], 1, 32.0
[CLEANUP], 13, 1.0
[CLEANUP], 13007, 1.0
[UPDATE], Operations, 500000
[UPDATE], AverageLatency(us), 9450.302092
[UPDATE], MinLatency(us), 52
[UPDATE], MaxLatency(us), 138367
[UPDATE], 95thPercentileLatency(us), 17359
[UPDATE], 99thPercentileLatency(us), 27167
[UPDATE], Return=OK, 500000
  • mongostat
$ mongostat 5
connected to: 127.0.0.1
insert  query update delete getmore command flushes mapped  vsize    res faults  locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
    *0     *0     *0     *0       0     0|0       0  4.03g  8.38g  2.02g      0  ycsb:0.0%          0       0|0     0|0    12b   635b     1   17:57:23
    *0   4428   4480     *0       0    61|0       0  4.03g  8.44g  2.62g      0 ycsb:14.0%          0      98|0     0|1     1m     5m   102   17:57:28
    *0  14708  14627     *0       0     0|0       0  4.03g  8.44g  2.71g      0 ycsb:39.1%          0      40|0    0|60     5m    18m   102   17:57:33
    *0  14720  14637     *0       0     0|0       0  4.03g  8.44g  2.71g      0 ycsb:38.9%          0      97|0     0|1     5m    18m   102   17:57:38
    *0  14875  14886     *0       0     0|0       0  4.03g  8.44g  3.07g      0 ycsb:39.4%          0      97|0     0|1     5m    18m   102   17:57:43
    *0  14684  14527     *0       0     0|0       0  4.03g  8.44g  2.54g      0 ycsb:39.0%          0      96|0     0|1     5m    18m   102   17:57:48
    *0  14762  14872     *0       0     0|0       0  4.03g  8.44g  2.32g      0 ycsb:39.6%          0      98|0     0|1     5m    18m   102   17:57:53
    *0  14675  14800     *0       0     0|0       0  4.03g  8.44g  3.01g      0 ycsb:39.2%          0      98|1     0|1     5m    18m   102   17:57:58
    *0   7144   7168     *0       0     0|0       0  4.03g  8.38g  2.02g      0 ycsb:19.5%          0       0|0     0|0     2m     9m     1   17:58:03
    *0     *0     *0     *0       0     0|0       0  4.03g  8.38g  2.02g      0  ycsb:0.0%          0       0|0     0|0    12b   635b     1   17:58:08

環境

  • c5.4xlarge

参考

2018-05-03

2018-04-08

Netflix のオープンソース可視化ツール FlameScope を使ってみた

Brendan Gregg らの所属する Netflix の cloud performance engineering team が FlameScope というパフォーマンス可視化ツールをオープンソースで公開した。詳しくは Netflix Tech Blog 参照。

flame graphs は瞬間的なスパイクを分析しづらかったが、FlameScope により1秒未満のヒートマップでイベント発生回数の多い時間帯が可視化されピンポイントで特定期間の flame graph を表示できるようになった。Oracle Database でいうと AWR/Statspack レポートだけでなく ASH 的な分析、さらに1秒未満のCPU時間の内訳のプロファイリングまで Craig Shallahamer の fulltime.sh でズームアップできるイメージ*1

FlameScope は Pyhton(フレームワークFlask) で書かれた Web アプリで、Perf で取得したデータを、ブラウザでアクセスして flame graph を分析するツールです。


Brendan Gregg は性能分析の大家でバックグラウンドは以下の通り。

Flame Graphs の作者の Brendan Gregg は Sun、Oracle、Joyent でカーネル、パフォーマンスのエンジニアとして活躍し、現在は Netflix(北米のインターネットのトラフィックの32.3%を占める。YouTubeは17.1%)*2 のシニア・パフォーマンス・アーキテクトです。ZFS L2ARC や DTrace Toolkit の開発者で、Solaris Performance and ToolsDTrace: Dynamic Tracing in Oracle Solaris, Mac OS X and FreeBSD の著者で、LinuxConFreeBSD SummitOaktable WorldAWS re:Invent などのイベントで幅広く活動されています。是非 Brendan Gregg’s Homepage をご覧ください。

perf + Flame Graphs で Linux カーネル内のボトルネックを特定する - ablog

FlameScope の見方

x軸が秒単位、y軸が1秒未満の時系列になっていて、赤いセルほどイベント発生回数が多い(CPU負荷が高い)。密度を高めるため2次元にしていると思われる。

f:id:yohei-a:20180408180622p:image:w360

実際のスクリーンショットはこんな感じで、x軸が秒単位、y軸が1秒未満の単位になっていて、

f:id:yohei-a:20180408180626p:image:w360

選択範囲の FlameGraph を表示することができる。

f:id:yohei-a:20180408180632p:image:w360

flame graph の見方は以下の通り。詳しくはこちら

  • 関数名で左から右にソートされている
  • コールスタックは上に行くほど深い
  • 最もコールスタックが深くて横幅が長いのがCPUを最も使っている関数

FlameScope を使ってみる

macOS に FlameScope をインストールして、Linux で perf で取得した性能情報をダウンロードして、FlameScope で可視化してみた。

f:id:yohei-a:20180408230316p:image:w360 f:id:yohei-a:20180408230323p:image:w360 f:id:yohei-a:20180408230329p:image:w360


環境
  • 性能情報取得環境
    • EC2インスタンスタイプ: c4.2xlarge
    • AMI: Amazon Linux AMI release 2017.09
    • Linux Kernel: 4.9.81-35.56.amzn1.x86_64
  • FlameScope実行環境
    • macOS Sierra 10.12.6

インストール
$ sudo yum -y install perf
$ git clone https://github.com/Netflix/flamescope
$ cd flamescope
$ sudo pip install -r requirements.txt

使ってみる
  • EC2 で perf で性能情報を取得しつつ openssl で負荷をかける
    • perf で性能情報を収集する
$ sudo perf record -F 49 -a -g -- sleep 120
$ sudo perf script --header > stacks.openssl.2018-04-07_01
$ gzip stacks.openssl.2018-04-07_01
$ ls -lh stacks.openssl.2018-04-07_01.gz
-rw-rw-r-- 1 ec2-user ec2-user 389K Apr  8 13:45 stacks.openssl.2018-04-07_01.gz
$ openssl speed -multi 4
  • macOS で FlameScope を起動する。
    • FlameScope を起動する
$ python run.py
    • flamescope/examples 以下に EC2 から stacks.openssl.2018-04-07_01.gz をコピーする。
    • ブラウザで http://127.0.0.1:5000/ にアクセスする。

スタックのリストが表示されるので、stacks.openssl.2018-04-07_01.gz をクリックする。

f:id:yohei-a:20180408230316p:image:w640

ヒートマップを表示すると綺麗に2分間計測したうち1分経過後から30秒間が赤くなっている。

f:id:yohei-a:20180408230323p:image:w640

範囲を選択してクリックすると flame graph を見ることができる。

f:id:yohei-a:20180408230329p:image:w640


参考


関連

*1:細かすぎて伝わらない例えかもしれない。。。

*2http://wazanova.jp/post/62392993571/30-netflix-amzazon

2017-09-18

sqlplus から Oracle Database に接続すると ORA-21561 で失敗する

事象

sqlplus から Oracle Database に接続すると ORA-21561 で失敗する。

% sqlplus awsuser/******@******.******.ap-northeast-1.rds.amazonaws.com:1521/ORCL

SQL*Plus: Release 12.1.0.2.0 Production on Mon Sep 18 22:37:57 2017

Copyright (c) 1982, 2016, Oracle.  All rights reserved.

ERROR:
ORA-21561: OID generation failed

ORA-21561: OID生成に失敗しました

原因: 渡されたハンドルが有効でない可能性があります。

処置: env、svcハンドルの妥当性を確認してください。

docs.oracle.com 404 error. We’re sorry, the page does not exist or is no longer available.

原因

  • /etc/hosts にホスト名のマッピングがない、もしくは間違っている。

Incorrect /etc/hosts mapping for the client machine or no mapping at all.

Sfaturi Oracle / Tips and tricks OracleDBA: ORA-21561 : OID generation failed

対処

  • ホスト名を確認する
% uname -n
******.***.foo.com
  • /etc/hosts に追記する
% sudo vi /etc/hosts
127.0.0.1	localhost ******.***.foo.com

環境

  • macOS Sierra
  • Oracle Instant Client for macOS (Intel x86) Version 12.1.0.2 (64-bit)

参考

2016-06-12

よく使う strace のオプション

Linux で strace を使ってシステムコールのトレースを調べる時によく使うオプションをメモ。

特にお気に入りのオプションは -T、-c、-ff & -o です。


書式

システムコールを詳細に追う
    • tt: 行頭にタイムスタンプを出力(マイクロ秒)
    • T: 行末にシステムコール内での所要時間を出力(マイクロ秒)
    • ff: 子プロセスのシステムコールもトレースし、-o との併用でプロセス(スレッド)毎に別ファイルに出力
    • o: 指定したファイル名に出力。-ff と併用すると、ファイル名.<PID> に出力
    • s: 出力文字数を指定。デフォルト32文字。read/write システムコールなどで読み書きした内容を全て確認したい場合は、大きくする。
    • p: プロセスIDを指定。
$ strace -Ttt -ff -s 1500000 -o <ログ出力先ファイル名> -p <PID>
もしくは
$ strace -Ttt -ff -s 1500000 -o <ログ出力先ファイル名> <コマンド>

strace したプロセスが起動している間に /proc/[pid]/fd でファイルディスクリプタ番号とファイルパスの対応を確認しておくと、strace で read(17, ... などと出力されている場合に、17 のファイルパス、つまりどのファイルを読んでいるかが分かります。

$ ls -l /proc/[pid]/fd

4.7 (2012年5月リリース) から -y、4.12 (2016年5月リリース) から -yy オプションでファイルディスクリプタ番号をファイル名、ソケットを送信元と送信先のIPアドレスとポート番号に置き換えてくれるようになっているようです。

strace -o out -y cp ubuntu-16.04-desktop-amd64.iso /tmp/blah 

We still get to keep the file descriptors, but it appends the filename of the file it was reading from! Awesome! We can see that it's reading 128KB (128 * 1024 = 131072 bytes) at a time from the source file (/home/bork/Desktop/ubuntu-16.04-desktop-amd64.iso), and writing them into the destination file (/tmp/blah). Seems reasonable!

read(3</home/bork/Desktop/ubuntu-16.04-desktop-amd64.iso>, "\315\350\5p\244\334\266\213 \2553~\37\7\330w\3125\316\360u\204P\236\255\n\244\344\264\327\213\241"..., 131072) = 131072
write(4</tmp/blah>, "\315\350\5p\244\334\266\213 \2553~\37\7\330w\3125\316\360u\204P\236\255\n\244\344\264\327\213\241"..., 131072) = 131072
read(3</home/bork/Desktop/ubuntu-16.04-desktop-amd64.iso>, "\37\367\336\377\247!\357\377\200\337wV\335\366|\232\337?\373iz\37r\376/z5\275\377\360\247\335"..., 131072) = 131072
write(4</tmp/blah>, "\37\367\336\377\247!\357\377\200\337wV\335\366|\232\337?\373iz\37r\376/z5\275\377\360\247\335"..., 131072) = 131072
read(3</home/bork/Desktop/ubuntu-16.04-desktop-amd64.iso>, "x\321/|'m\25\313o \261t^b\306\17r4~\3138j\6\4\244\3308\300E\366\364\22"..., 131072) = 131072
write(4</tmp/blah>, "x\321/|'m\25\313o \261t^b\306\17r4~\3138j\6\4\244\3308\300E\366\364\22"..., 131072) = 131072
read(3</home/bork/Desktop/ubuntu-16.04-desktop-amd64.iso>, "j\273\324\332\216\361\207\204\336\243\326\267\227\35\322\370\205\245N6+\211h\246\215\32k\336\0\r\320."..., 131072) = 131072
write(4</tmp/blah>, "j\273\324\332\216\361\207\204\336\243\326\267\227\35\322\370\

...

If you run strace with -yy, and you're doing networking, it'll resolve file descriptors into a source & destination IP address and port, like this!

This is querying my DNS server on localhost for blah.com and getting no answer.

$ strace -yy wget blah.com
recvfrom(3<UDP:[127.0.0.1:46218->127.0.1.1:53]>, "\270\222\201\205\0\1\0\0\0\0\0\0\4blah\3com\0\0\1\0\1", 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.1.1")}, [16]) = 26
no title

システムコールの種類別に集計(時間・回数)する
$ strace -fc -o <ログ出力先ファイル名> -p <PID>
もしくは
$ strace -fc -o <ログ出力先ファイル名> <コマンド>

実行例

システムコールを詳細に追う
$ ps -ef|grep [t]nslsnr
oracle    55447      1  0 Feb09 ?        00:04:00 /u01/app/12.1.0.2/grid/bin/tnslsnr MGMTLSNR -no_crs_notify -inherit
oracle    56996      1  0 Feb09 ?        00:33:21 /u01/app/12.1.0.2/grid/bin/tnslsnr LISTENER_SCAN3 -no_crs_notify -inherit
oracle    69013      1  0 Mar03 ?        01:29:18 /u01/app/12.1.0.2/grid/bin/tnslsnr LISTENER -no_crs_notify -inherit
$ ls -l /proc/55447/fd                                                                                                                        
total 0
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 0 -> /dev/null
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 1 -> /dev/null
l-wx------. 1 oracle oinstall 64 Mar 19 02:18 10 -> pipe:[28070704]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 11 -> socket:[28104650]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 12 -> socket:[28104651]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 13 -> socket:[28107334]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 14 -> socket:[28107317]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 15 -> socket:[28088239]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 16 -> socket:[28107433]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 17 -> socket:[28107447]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 18 -> socket:[28188383]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 19 -> socket:[28188384]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 2 -> /dev/null
lr-x------. 1 oracle oinstall 64 Mar 19 02:18 3 -> /u01/app/12.1.0.2/grid/rdbms/mesg/diaus.msb
lr-x------. 1 oracle oinstall 64 Mar 19 02:18 4 -> /proc/55447/fd
lr-x------. 1 oracle oinstall 64 Mar 19 02:18 5 -> /u01/app/12.1.0.2/grid/network/mesg/nlus.msb
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 6 -> anon_inode:[eventpoll]
lr-x------. 1 oracle oinstall 64 Mar 19 02:18 7 -> pipe:[28070703]
lr-x------. 1 oracle oinstall 64 Mar 19 02:18 8 -> /u01/app/12.1.0.2/grid/network/mesg/tnsus.msb
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 9 -> socket:[28104649]
$ strace -Ttt -ff -s 1500000 -o strace -p 55447
Process 55447 attached with 2 threads - interrupt to quit
^CProcess 55447 detached
Process 55470 detached
$ ls
strace.55447  strace.55470
o と ff オプションにより、スレッド別にファイルが生成されている
$ head strace.55447                                                                                                       
12:14:50.669465★タイムスタンプ(-tt) epoll_wait(6, {{EPOLLIN, {u32=39785040, u64=39785040}}}, 1024, 4294967295) = 1 <7.441963>★システムコールで使った時間(-T)
12:14:58.111594 times(NULL)             = 1506816866 <0.000013>
12:14:58.111651 getsockname(9★, {sa_family=AF_FILE, path="/var/tmp/.oracle/sMGMTLSNR"}, [29]) = 0 <0.000014> 
↑ファイルディスクリプタ番号9"socket:[28104649]"
12:14:58.111716 chmod("/var/tmp/.oracle/sMGMTLSNR", 0777) = 0 <0.000029>
12:14:58.111784 accept(9, {sa_family=AF_FILE, NULL}, [2]) = 20 <0.000019>
12:14:58.111836 fcntl(20, F_SETFD, FD_CLOEXEC) = 0 <0.000011>
12:14:58.111877 times(NULL)             = 1506816866 <0.000011>
12:14:58.111967 rt_sigaction(SIGPIPE, {SIG_IGN, ~[ILL ABRT BUS FPE SEGV USR2 TERM XCPU XFSZ SYS RTMIN RT_1], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x7f27716f9710}, {SIG_IGN, ~[ILL ABRT BUS FPE KILL SEGV USR2 TERM STOP XCPU XFSZ SYS RTMIN RT_1], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x7f27716f9710}, 8) = 0 <0.000013>
12:14:58.112057 epoll_ctl(6, EPOLL_CTL_ADD, 20, {EPOLLIN, {u32=40329456, u64=40329456}}) = 0 <0.000016>
12:14:58.112109 times(NULL)             = 1506816866 <0.000011>
システムコールの種類別に集計(時間・回数)する
$ ps -ef|grep [j]ava
oracle    10498  10412  0 Apr21 ?        11:37:56 /u01/app/emcc/agent/core/12.1.0.4.0/jdk/bin/java ...

...

$ strace -fc -o strace.log -p 10498
Process 10498 attached with 236 threads - interrupt to quit
^CProcess 10498 detached
Process 10499 detached
Process 10500 detached

...

$ cat strace.log
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 69.28    0.171635         439       391        98 futex
 15.34    0.037999        1809        21        13 restart_syscall
 10.84    0.026860          86       313           sched_yield
  4.04    0.009999        5000         2           epoll_wait
  0.40    0.001000          48        21           recvfrom
  0.06    0.000156           6        27         6 stat
  0.04    0.000106          18         6           write
  0.00    0.000000           0         4           read
  0.00    0.000000           0         7           open
  0.00    0.000000           0        11           close
  0.00    0.000000           0         8           fstat
  0.00    0.000000           0         1           poll
  0.00    0.000000           0         3           lseek
  0.00    0.000000           0         4           mprotect
  0.00    0.000000           0         1           access
  0.00    0.000000           0         2           dup2
  0.00    0.000000           0         4           socket
  0.00    0.000000           0         3           connect
  0.00    0.000000           0        13           sendto
  0.00    0.000000           0         3           recvmsg
  0.00    0.000000           0         1           bind
  0.00    0.000000           0         3           getsockname
  0.00    0.000000           0         2           setsockopt
  0.00    0.000000           0         3           getsockopt
  0.00    0.000000           0         1           uname
  0.00    0.000000           0        14           fcntl
  0.00    0.000000           0         7           rename
  0.00    0.000000           0         6         5 unlink
  0.00    0.000000           0        24           clock_gettime
------ ----------- ----------- --------- --------- ----------------
100.00    0.247755                   906       122 total

関連


参考

       -c          Count time, calls, and errors for each system call and
                   report a summary on program exit.  On Linux, this
                   attempts to show system time (CPU time spent running in
                   the kernel) independent of wall clock time.  If -c is
                   used with -f or -F (below), only aggregate totals for all
                   traced processes are kept.
...
       -ff         If the -o filename option is in effect, each processes
                   trace is written to filename.pid where pid is the numeric
                   process id of each process.  This is incompatible with
                   -c, since no per-process counts are kept.
...
       -t          Prefix each line of the trace with the time of day.

       -tt         If given twice, the time printed will include the
                   microseconds.

       -ttt        If given thrice, the time printed will include the
                   microseconds and the leading portion will be printed as
                   the number of seconds since the epoch.

       -T          Show the time spent in system calls.  This records the
                   time difference between the beginning and the end of each
                   system call.
...
       -o filename Write the trace output to the file filename rather than
                   to stderr.  Use filename.pid if -ff is used.  If the
                   argument begins with '|' or with '!' then the rest of the
                   argument is treated as a command and all output is piped
                   to it.  This is convenient for piping the debugging
                   output to a program without affecting the redirections of
                   executed programs.
...
       -p pid      Attach to the process with the process ID pid and begin
                   tracing.  The trace may be terminated at any time by a
                   keyboard interrupt signal (CTRL-C).  strace will respond
                   by detaching itself from the traced process(es) leaving
                   it (them) to continue running.  Multiple -p options can
                   be used to attach to many processes in addition to
                   command (which is optional if at least one -p option is
                   given).  -p "`pidof PROG`" syntax is supported.
...
       -s strsize  Specify the maximum string size to print (the default is
                   32).  Note that filenames are not considered strings and
                   are always printed in full.
       /proc/[pid]/fd/
              This is a subdirectory containing one entry for each file
              which the process has open, named by its file descriptor, and
              which is a symbolic link to the actual file.  Thus, 0 is
              standard input, 1 standard output, 2 standard error, and so
              on.

              For file descriptors for pipes and sockets, the entries will
              be symbolic links whose content is the file type with the
              inode.  A readlink(2) call on this file returns a string in
              the format:

                  type:[inode]