Hatena::ブログ(Diary)

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

2018-09-04

Amazon Redshift で取得できる監査ログ

設定

監査ログの有効化

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

  • [監査ログ記録の設定]で以下の通り入力する
    • 監査ログ記録の有効化: はい
    • 監査ログ記録の有効化: 新規作成
    • 新規バケット名: redshift-trail-ds2xl2n(任意の名前)

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

ユーザーアクティティログ取得設定
  • Redshift のパラメータグループを作成し enable_user_activity_logging を true に設定する。

f:id:yohei-a:20180909210817p:image

確認する

接続ログ

認証の試みと、接続および切断を記録します。次の表に、接続ログの情報を示します。

列名説明
event接続または認証イベント。
recordtimeイベントが発生した時刻。
remotehostリモートホストの名前または IP アドレス。
remoteportリモートホストのポート番号。
pidステートメントに関連付けられるプロセス ID。
dbnameデータベース名。
usernameユーザー名。
authmethod認証方法。
duration接続時間 (マイクロ秒)。
sslversionSecure Sockets Layer (SSL) バージョン。
sslcipherSSL 暗号
mtu最大送信単位 (MTU)。
sslcompressionSSL 圧縮タイプ。
sslexpansionSSL 拡張タイプ。
  • 100000000000_redshift_ap-northeast-1_ds2xl2n_connectionlog_2018-09-04T07:16.gz
    • redshift-trail-ds2xl2n/AWSLogs/100000000000/redshift/ap-northeast-1/2018/09/04/
authenticated |Tue, 4 Sep 2018 06:16:36:393|::ffff:127.0.0.1 |53154 |13647|dev |rdsdb |password |0| | |0| | | |
initiating session |Tue, 4 Sep 2018 06:16:36:393|::ffff:127.0.0.1 |53154 |13647|dev |rdsdb |password |0| | |0| | | |
authenticated |Tue, 4 Sep 2018 06:19:30:621|::ffff:**.*.*.145 |25692 |13965|mydb |awsuser |password |0|TLSv1.2 |ECDHE-RSA-AES256-GCM-SHA384 |0| | | |
initiating session |Tue, 4 Sep 2018 06:19:30:621|::ffff:**.*.*.145 |25692 |13965|mydb |awsuser |password |0|TLSv1.2 |ECDHE-RSA-AES256-GCM-SHA384 |0| | | |
set application_name |Tue, 4 Sep 2018 06:19:30:621|::ffff:**.*.*.145 |25692 |13965|mydb |awsuser |password |159643|TLSv1.2 |ECDHE-RSA-AES256-GCM-SHA384 |0| | | |psql
disconnecting session |Tue, 4 Sep 2018 06:36:28:431|::ffff:**.*.*.145 |25692 |13965|mydb |awsuser |password |1017969825|TLSv1.2 |ECDHE-RSA-AES256-GCM-SHA384 |0| | | |psql
disconnecting session |Tue, 4 Sep 2018 06:36:36:366|::ffff:127.0.0.1 |53154 |13647|dev |rdsdb |password |1199973731| | |0| | | |

ユーザーログ

データベースユーザーに対する操作を記録する。

  • ユーザーの作成
  • ユーザーの削除
  • ユーザーの変更 (名前の変更)
  • ユーザーの変更 (プロパティの変更)
列名説明
userid変更の影響を受けるユーザーの ID。
username変更の影響を受けるユーザーのユーザー名。
oldusername名前の変更アクションの場合、以前のユーザー名。その他のアクションの場合、このフィールドは空です。
action実行されたアクション。有効な値: Alter 作成 Drop Rename
usecreatedbtrue (1) の場合、ユーザーに create database 権限があることを示します。
usesupertrue (1) の場合、ユーザーがスーパーユーザーであることを示します。
usecatupdtrue (1) の場合、ユーザーはシステムカタログを更新できることを示します。
valuntilパスワードが失効する日付。
pidプロセス ID。
xidトランザクション ID。
recordtimeUTC で表されたクエリの開始時間。

ユーザーアクティティログ

クエリ実行単位のログ

列名説明
recordtimeイベントが発生した時刻。
dbデータベース名。
ユーザーユーザー名。
pidステートメントに関連付けられるプロセス ID。
useridユーザー ID
xidトランザクション ID。
queryプレフィックス LOG の後に、改行を含むクエリのテキストが続きます。
  • 100000000000_redshift_ap-northeast-1_ds2xl2n_useractivitylog_2018-09-04T06:16.gz
    • redshift-trail-ds2xl2n/AWSLogs/100000000000/redshift/ap-northeast-1/2018/09/04/
'2018-09-04T05:34:50Z UTC [ db=mydb user=awsuser pid=9972 userid=100 xid=7200 ]' LOG: select * from STL_USERLOG;
'2018-09-04T05:34:50Z UTC [ db=mydb user=awsuser pid=9972 userid=100 xid=7200 ]' LOG: SELECT pg_catalog.stl_userlog.userid AS userid, pg_catalog.stl_userlog.username AS username, pg_catalog.stl_userlog.oldusernam
e AS oldusername, pg_catalog.stl_userlog.action AS action, pg_catalog.stl_userlog.usecreatedb AS usecreatedb, pg_catalog.stl_userlog.usesuper AS usesuper, pg_catalog.stl_userlog.usecatupd AS usecatupd, pg_catalog
.stl_userlog.valuntil AS valuntil, pg_catalog.stl_userlog.pid AS pid, pg_catalog.stl_userlog.xid AS xid, pg_catalog.stl_userlog.recordtime AS recordtime FROM pg_catalog.stl_userlog;



参考

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-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


環境

インストール
$ 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)

参考