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

Spark SQL on EMR に JDBC 接続する

Spark SQL on EMR に JDBC 接続したメモ。


  • EMRクラスタを作成する
    • Release label:emr-5.12.0
    • Hadoop distribution:Amazon 2.8.3
    • Applications:Hive 2.3.2, Pig 0.17.0, Hue 4.1.0, Zeppelin 0.7.3, Spark 2.2.1, Presto 0.188
ssh -i ~/mykey.pem hadoop@ec2-**-***-***-**.ap-northeast-1.compute.amazonaws.com
  • thriftserver を起動する
$ sudo -u spark /usr/lib/spark/sbin/start-thriftserver.sh
  • 接続してみる
$ sudo -u spark /usr/lib/spark/bin/beeline
Beeline version 1.2.1-spark2-amzn-0 by Apache Hive
beeline> !connect jdbc:hive2://localhost:10001
Connecting to jdbc:hive2://localhost:10001
Enter username for jdbc:hive2://localhost:10001: hadoop
Enter password for jdbc:hive2://localhost:10001:<Return>
18/03/21 10:51:29 INFO Utils: Supplied authorities: localhost:10001
18/03/21 10:51:29 INFO Utils: Resolved authority: localhost:10001
18/03/21 10:51:29 INFO HiveConnection: Will try to open client transport with JDBC Uri: jdbc:hive2://localhost:10001
Connected to: Spark SQL (version 2.2.1)
Driver: Hive JDBC (version 1.2.1-spark2-amzn-0)
Transaction isolation: TRANSACTION_REPEATABLE_READ
0: jdbc:hive2://localhost:10001> show tables;
+-----------+------------+--------------+--+
| database  | tableName  | isTemporary  |
+-----------+------------+--------------+--+
+-----------+------------+--------------+--+
No rows selected (1.201 seconds)
0: jdbc:hive2://localhost:10001>
  • 切断する
0: jdbc:hive2://localhost:10001> !exit
Closing: 0: jdbc:hive2://localhost:10001
Error: Error while cleaning up the server resources (state=,code=0)
Connection is already closed.

参考

2018-03-17

Aurora Postgres で実行したクエリをログに出力する

設定

  • DB パラメータグループを作成して以下の通り設定する
    • log_statement:all
    • log_min_duration_statement: 1
    • log_destination: csvlog
  • DBインスタンスに作成したパラメータグループを設定する

設定確認

  • AWSマネジメントコンソールで確認できるが、接続しているセッションで以下の通り確認できる。
% psql "host=aurora-postgres-r42xl.*********.ap-northeast-1.rds.amazonaws.com user=****** dbname=mydb port=5432"
Password:
Timing is on.
psql (9.6.2, server 9.6.6)
SSL connection (protocol: TLSv1.2, cipher: ECDHE-RSA-AES256-GCM-SHA384, bits: 256, compression: off)
Type "help" for help.

aurora-postgres-r42xl awsuser 07:06 => show log_statement;
 log_statement
---------------
 all
(1 row)

Time: 14.281 ms
aurora-postgres-r42xl awsuser 07:06 => show log_min_duration_statement;
 log_min_duration_statement
----------------------------
 1ms
(1 row)

Time: 13.284 ms

クエリを確認する

  • AWSマネジメントコンソールから error/postgresql.log.*.csv を確認する。

参考

DB インスタンスに関連付けられている DB パラメータグループの 2 つパラメーター log_statement と log_min_duration_statement を設定することで、PostgreSQL DB インスタンスのクエリログ記録を有効にすることができます。log_statement パラメーターでは、どの SQL ステートメントをログに記録するかを制御します。このパラメーターを all に設定して、すべてのステートメントがログに記録されるようにすることをお勧めします。デフォルト値は none です。または、この値を ddl に設定して、すべてのデータ定義言語 (DDL) ステートメント (CREATE、ALTER、DROP など) がログに記録されるようにすることもできます。さらに、mod に設定して、すべての DDL とデータ変更言語 (DML) ステートメント (INSERT、UPDATE、DELETE) がログに記録されるようにすることもできます。

log_min_duration_statement パラメーターでは、ログに記録するステートメントの制限をミリ秒単位で設定します。このパラメーターで設定した時間より長く実行されたすべての SQL ステートメントがログに記録されます。このパラメーターはデフォルトでは無効になっており、マイナス 1 (-1) に設定されています。このパラメーターを有効にすると、最適化されていないクエリを見つけるために役立ちます。これらの設定の詳細については、PostgreSQL のドキュメントの「エラー報告とログ記録」を参照してください。

PostgreSQL データベースのログファイル - Amazon Relational Database Service

log_statement (enum)

Controls which SQL statements are logged. Valid values are none (off), ddl, mod, and all (all statements). ddl logs all data definition statements, such as CREATE, ALTER, and DROP statements. mod logs all ddl statements, plus data-modifying statements such as INSERT, UPDATE, DELETE, TRUNCATE, and COPY FROM. PREPARE, EXECUTE, and EXPLAIN ANALYZE statements are also logged if their contained command is of an appropriate type. For clients using extended query protocol, logging occurs when an Execute message is received, and values of the Bind parameters are included (with any embedded single-quote marks doubled).

https://www.postgresql.org/docs/9.6/static/runtime-config-logging.html

log_min_duration_statement (integer)

Causes the duration of each completed statement to be logged if the statement ran for at least the specified number of milliseconds. Setting this to zero prints all statement durations. Minus-one (the default) disables logging statement durations. For example, if you set it to 250ms then all SQL statements that run 250ms or longer will be logged. Enabling this parameter can be helpful in tracking down unoptimized queries in your applications. Only superusers can change this setting.

https://www.postgresql.org/docs/9.6/static/runtime-config-logging.html

2018-03-16

Aurora Postgres で track_activity_query_size を変更して pg_stat_activity.query に記録されるクエリの長さを拡張する

設定変更

  • パラメーターグループを作成する
    • パラメータグループファミリー: aurora-postgresql9.6
    • タイプ: DB Parameter Group
    • グループ名: custom.aurora-postgresql9.6 (任意)
    • 説明: Custom parameter group for aurora-postgresql9.6(任意)
  • track_activity_query_size を 102400 に変更する
    • 作成したDBパラメーターグループ "custom.aurora-postgresql9.6" の track_activity_query_size を 102400(最大値) に変更する。
  • 作成したDBパラメーターグループを関連付ける
    • Aurora Postgres インスタンスのDB パラメータグループを作成したパラメーターグループ "custom.aurora-postgresql9.6" に変更する。
  • Aurora Postgres インスタンスを再起動する
    • DBインスタンスのDBパラメーターグループの表示が "aurora-postgres96-custom (再起動の保留中)" のように "再起動の保留中" と表示されたら、DBインスタンスを再起動する。

確認

  • track_activity_query_size の値を確認する。
aurora-postgres-r42xl awsuser 05:37 => show track_activity_query_size;
 track_activity_query_size
---------------------------
 102400
(1 row)

Time: 12.975 ms
  • 1024バイトを超えるクエリを実行してみて、pg_stat_activity.query で確認する。
select datid,
	datname,
	pid,
	usesysid,
	usename,
	application_name,
	client_addr,
	client_hostname,
	client_port,
	backend_start,
	xact_start,
	query_start,
	state_change,
	wait_event_type,
	wait_event,
	state,
	backend_xid,
	backend_xmin,
	query 
	from pg_stat_activity
union
select datid,
	datname,
	pid,
	usesysid,
	usename,
	application_name,
	client_addr,
	client_hostname,
	client_port,
	backend_start,
	xact_start,
	query_start,
	state_change,
	wait_event_type,
	wait_event,
	state,
	backend_xid,
	backend_xmin,
	query 
	from pg_stat_activity
union
(続く)
;
  • 上のクエリを実行する。

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

  • pg_stat_activity.query が 1024 バイトを超えて 5852 バイトまで表示されている。

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


補足

  • デフォルトのパラメーターグループの設定では以下の通り1023バイトまでしか表示されない。

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

2018-03-10

MySQL InnoDB で大きなトランザクションを見つける

SHOW ENGINE INNODB STATUS の

  • History list length が MySQL インスタンス全体の UNDO ページ数
  • undo log entries がトランザクション毎のUNDOレコード数

で、History list length が大きいとMySQLインスタンス全体での UNDO のサイズが大きくなりロールバックにかかる時間が長くなっており、undo log entries が大きいトランザクションが UNDO ページを大量に使っている犯人だと類推できる。undo log entries は insert/update/delete などを行った行数(未コミット)でサイズではない。

MariaDB 5.5.27以降10未満(XtraDB)では Information Schema の INNODB_UNDO_LOGS. SIZE で undo log が使っているサイズを確認できる。


  • テーブルを作成する
> create table undo_test(
	col1 char(255),
	col2 char(255),
	col3 char(255),
	col4 char(255),
	col5 char(255)
);
  • 1行 insert する
> start transaction;
> insert into undo_test(col1) values('1');
  • トランザクションが使っているUNDOの量を調べる
> show engine innodb stauts\G
(中略)
------------
TRANSACTIONS
------------
TRANSACTIONS
------------
Trx id counter 111207046
Purge done for trx's n:o < 111206999 undo n:o < 0 state: running but idle
History list length 719 ★ history list length がインスタンス全体のUNDOページ数
LIST OF TRANSACTIONS FOR EACH SESSION:
(中略)
---TRANSACTION 111207036, ACTIVE 2 sec ★2秒経過
1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1 ★1行insertしたので、undo log が 1になっている
MySQL thread id 8697(★スレッドID), OS thread handle 0x2b9eb4b47700, query id 1400669 27.0.3.145(★接続元IP) awsuser(★ユーザー名) delayed send ok done
  • 5行 insert する
> start transaction;
> insert into undo_test(col1) values('2');
> insert into undo_test(col1) values('3');
> insert into undo_test(col1) values('4');
> insert into undo_test(col1) values('5');
  • 行数を確認する
> select count(1) from undo_test;
+----------+
| count(1) |
+----------+
|        5 |
+----------+
1 row in set (0.01 sec)
  • トランザクションが使っているUNDOの量を調べる
> show engine innodb stauts\G
(中略)
------------
TRANSACTIONS
------------
Trx id counter 111207337
Purge done for trx's n:o < 111206999 undo n:o < 0 state: running but idle
History list length 808
LIST OF TRANSACTIONS FOR EACH SESSION:
(中略)
---TRANSACTION 111207036, ACTIVE 58 sec ★58秒経過
1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 5 ★5行insertしたので、undo log が 5 になっている
MySQL thread id 8697, OS thread handle 0x2b9ef9e43700, query id 1400956 27.0.3.145 awsuser cleaned up
Trx read view will not see trx with id >= 111207290, sees < 111207036
  • セッションを kill する
> call mysql.rds_kill(8697); ★show engine innodb stauts の TRANSACTIONS に表示されていた MySQL thread id 
  • トランザクションが終了していることを確認する
> show engine innodb status\G
(中略)
------------
TRANSACTIONS
------------
Trx id counter 111208582
Purge done for trx's n:o < 111206999 undo n:o < 0 state: running but idle
History list length 726
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 111208485, not started
MySQL thread id 8719, OS thread handle 0x2b9eb4a43700, query id 1402459 localhost rdsadmin cleaned up
---TRANSACTION 111205044, not started
MySQL thread id 8664, OS thread handle 0x2b9eb4bc9700, query id 1402491 27.0.3.145 awsuser System lock
show engine innodb status
---TRANSACTION 111208058, not started
MySQL thread id 11, OS thread handle 0x2b9eb37ed700, query id 1401866 localhost rdsadmin delayed send ok done
---TRANSACTION 111208576, not started
MySQL thread id 2, OS thread handle 0x2b9eb4a43700, query id 1402490 localhost rdsadmin delayed send ok done
★トランザクションがなくなっている

参考

Global history and purge operations

In addition to every record having a reference to its previous version, there is also a global view of the history of the entire database, called the “history list”. As each transaction is committed, its history is linked into this global history list in transaction serialization (commit) order. The history list is used primarily for cleaning up after a transaction, once no existing read view still needs its history (all other transactions have completed).

In the background, InnoDB runs a continuous “purge” process which is responsible for two things:

  • Actually deleting delete-marked records2, if the current version of the record in the index at the time of purge is still delete-marked and bears the same transaction ID. (That is, the record hasn’t been re-inserted.)
  • Freeing undo log pages and unlinking them from the global history list to make them available for re-use.

InnoDB exposes the total amount of history present in the system as a “History list length”, which can be seen in SHOW ENGINE INNODB STATUS. This is the count of all database modifications present in the undo logs, in units of undo logs (which may contain a single record modification or many).

The basics of the InnoDB undo logging and history system – Jeremy Cole

XtraDB は Information Schema の INNODB_UNDO_LOGS. SIZE(Size in pages of the segment) で undo log が使っているサイズが分かる。MariaDB 5.5.27 で入って、10では削除されてる。

Information Schema INNODB_UNDO_LOGS Table

The Information Schema INNODB_UNDO_LOGS table is a Percona enchancement, and is only available for XtraDB, not InnoDB (see XtraDB and InnoDB). It contains information about the the InnoDB undo log, with each record being an undo log segment. It was removed in MariaDB 10.0.

It has the following columns:

  • ColumnDescription
  • TRX_ID: Unique transaction ID number, matching the value from the information_schema.INNODB_TRX table.
  • RSEG_ID: Rollback segment ID, matching the value from the information_schema.INNODB_RSEG table.
  • USEG_ID: Undo segment ID.
  • SEGMENT_TYPE: Indicates the operation type, for example INSERT or UPDATE.
  • STATE: Segment state: one of ACTIVE (contains active transaction undo log), CACHED, TO_FREE (insert undo segment can be freed), TO_PURGE (update undo segment won't be re-used and can be purged when all undo data is removed) or PREPARED (segment of a prepared transaction).
  • SIZE: Size in pages of the segment.
Information Schema INNODB_UNDO_LOGS Table - MariaDB Knowledge Base

ソースコード

  • mysql-5.6.10/storage/innobase/lock/lock0lock.cc
/*********************************************************************//**
Prints info of locks for all transactions.
@return FALSE if not able to obtain lock mutex
and exits without printing info */
UNIV_INTERN
ibool
lock_print_info_summary(
/*====================*/
        FILE*   file,   /*!< in: file where to print */
        ibool   nowait) /*!< in: whether to wait for the lock mutex */
{
        /* if nowait is FALSE, wait on the lock mutex,
        otherwise return immediately if fail to obtain the
        mutex. */
        if (!nowait) {
                lock_mutex_enter();
        } else if (lock_mutex_enter_nowait()) {
                fputs("FAIL TO OBTAIN LOCK MUTEX, "
                      "SKIP LOCK INFO PRINTING\n", file);
                return(FALSE);
        }

        if (lock_deadlock_found) {
                fputs("------------------------\n"
                      "LATEST DETECTED DEADLOCK\n"
                      "------------------------\n", file);

                if (!srv_read_only_mode) {
                        ut_copy_file(file, lock_latest_err_file);
                }
        }

        fputs("------------\n"
              "TRANSACTIONS\n"
              "------------\n", file);

        fprintf(file, "Trx id counter " TRX_ID_FMT "\n",
                trx_sys_get_max_trx_id());

        fprintf(file,
                "Purge done for trx's n:o < " TRX_ID_FMT
                " undo n:o < " TRX_ID_FMT " state: ",
                purge_sys->iter.trx_no,
                purge_sys->iter.undo_no);

        /* Note: We are reading the state without the latch. One because it
        will violate the latching order and two because we are merely querying
        the state of the variable for display. */

        switch (purge_sys->state){
        case PURGE_STATE_EXIT:
        case PURGE_STATE_INIT:
                /* Should never be in this state while the system is running. */
                ut_error;

        case PURGE_STATE_DISABLED:
                fprintf(file, "disabled");
                break;

        case PURGE_STATE_RUN:
                fprintf(file, "running");
                /* Check if it is waiting for more data to arrive. */
                if (!purge_sys->running) {
                        fprintf(file, " but idle");
                }
                break;

        case PURGE_STATE_STOP:
                fprintf(file, "stopped");
                break;
        }

        fprintf(file, "\n");

        fprintf(file,
                "History list length %lu\n",
                (ulong) trx_sys->rseg_history_len);

#ifdef PRINT_NUM_OF_LOCK_STRUCTS
        fprintf(file,
                "Total number of lock structs in row lock hash table %lu\n",
                (ulong) lock_get_n_rec_locks());
#endif /* PRINT_NUM_OF_LOCK_STRUCTS */
        return(TRUE);
}
  • mysql-5.6.10/storage/innobase/trx/trx0trx.cc
/**********************************************************************//**
Prints info about a transaction.
Caller must hold trx_sys->mutex. */
UNIV_INTERN
void
trx_print_low(
/*==========*/
        FILE*           f,
                        /*!< in: output stream */
        const trx_t*    trx,
                        /*!< in: transaction */
        ulint           max_query_len,
                        /*!< in: max query length to print,
                        or 0 to use the default max length */
        ulint           n_rec_locks,
                        /*!< in: lock_number_of_rows_locked(&trx->lock) */
        ulint           n_trx_locks,
                        /*!< in: length of trx->lock.trx_locks */
        ulint           heap_size)
                        /*!< in: mem_heap_get_size(trx->lock.lock_heap) */
{
        ibool           newline;
        const char*     op_info;

        ut_ad(mutex_own(&trx_sys->mutex));

        fprintf(f, "TRANSACTION " TRX_ID_FMT, trx->id);

        /* trx->state cannot change from or to NOT_STARTED while we
        are holding the trx_sys->mutex. It may change from ACTIVE to
        PREPARED or COMMITTED. */
        switch (trx->state) {
        case TRX_STATE_NOT_STARTED:
                fputs(", not started", f);
                goto state_ok;
        case TRX_STATE_ACTIVE:
                fprintf(f, ", ACTIVE %lu sec",
                        (ulong) difftime(time(NULL), trx->start_time));
                goto state_ok;
        case TRX_STATE_PREPARED:
                fprintf(f, ", ACTIVE (PREPARED) %lu sec",
                        (ulong) difftime(time(NULL), trx->start_time));
                goto state_ok;
        case TRX_STATE_COMMITTED_IN_MEMORY:
                fputs(", COMMITTED IN MEMORY", f);
                goto state_ok;
        }
        fprintf(f, ", state %lu", (ulong) trx->state);
        ut_ad(0);
state_ok:

        /* prevent a race condition */
        op_info = trx->op_info;

        if (*op_info) {
                putc(' ', f);
                fputs(op_info, f);
        }

        if (trx->is_recovered) {
                fputs(" recovered trx", f);
        }

        if (trx->declared_to_be_inside_innodb) {
                fprintf(f, ", thread declared inside InnoDB %lu",
                        (ulong) trx->n_tickets_to_enter_innodb);
        }

        putc('\n', f);

        if (trx->n_mysql_tables_in_use > 0 || trx->mysql_n_tables_locked > 0) {
                fprintf(f, "mysql tables in use %lu, locked %lu\n",
                        (ulong) trx->n_mysql_tables_in_use,
                        (ulong) trx->mysql_n_tables_locked);
        }

        newline = TRUE;

        /* trx->lock.que_state of an ACTIVE transaction may change
        while we are not holding trx->mutex. We perform a dirty read
        for performance reasons. */

        switch (trx->lock.que_state) {
        case TRX_QUE_RUNNING:
                newline = FALSE; break;
        case TRX_QUE_LOCK_WAIT:
                fputs("LOCK WAIT ", f); break;
        case TRX_QUE_ROLLING_BACK:
                fputs("ROLLING BACK ", f); break;
        case TRX_QUE_COMMITTING:
                fputs("COMMITTING ", f); break;
        default:
                fprintf(f, "que state %lu ", (ulong) trx->lock.que_state);
        }

        if (n_trx_locks > 0 || heap_size > 400) {
                newline = TRUE;

                fprintf(f, "%lu lock struct(s), heap size %lu,"
                        " %lu row lock(s)",
                        (ulong) n_trx_locks,
                        (ulong) heap_size,
                        (ulong) n_rec_locks);
        }

        if (trx->has_search_latch) {
                newline = TRUE;
                fputs(", holds adaptive hash latch", f);
        }

        if (trx->undo_no != 0) {
                newline = TRUE;
                fprintf(f, ", undo log entries "TRX_ID_FMT, trx->undo_no);
        }

        if (newline) {
                putc('\n', f);
        }

        if (trx->mysql_thd != NULL) {
                innobase_mysql_print_thd(f, trx->mysql_thd, max_query_len);
        }
}
  • mysql-5.6.10/storage/innobase/handler/ha_innodb.cc
/************************************************************************//**
Implements the SHOW ENGINE INNODB STATUS command. Sends the output of the
InnoDB Monitor to the client.
@return 0 on success */
static
int
innodb_show_status(
/*===============*/
        handlerton*     hton,   /*!< in: the innodb handlerton */
        THD*            thd,    /*!< in: the MySQL query thread of the caller */
        stat_print_fn*  stat_print)
{
        trx_t*                  trx;
        static const char       truncated_msg[] = "... truncated...\n";
        const long              MAX_STATUS_SIZE = 1048576;
        ulint                   trx_list_start = ULINT_UNDEFINED;
        ulint                   trx_list_end = ULINT_UNDEFINED;

        DBUG_ENTER("innodb_show_status");
        DBUG_ASSERT(hton == innodb_hton_ptr);

        /* We don't create the temp files or associated
        mutexes in read-only-mode */

        if (srv_read_only_mode) {
                DBUG_RETURN(0);
        }

        trx = check_trx_exists(thd);

        trx_search_latch_release_if_reserved(trx);

        innobase_srv_conc_force_exit_innodb(trx);

        /* We let the InnoDB Monitor to output at most MAX_STATUS_SIZE
        bytes of text. */

        char*   str;
        ssize_t flen, usable_len;

        mutex_enter(&srv_monitor_file_mutex);
        rewind(srv_monitor_file);

        srv_printf_innodb_monitor(srv_monitor_file, FALSE,
                                  &trx_list_start, &trx_list_end);

        os_file_set_eof(srv_monitor_file);

        if ((flen = ftell(srv_monitor_file)) < 0) {
                flen = 0;
        }

        if (flen > MAX_STATUS_SIZE) {
                usable_len = MAX_STATUS_SIZE;
                srv_truncated_status_writes++;
        } else {
                usable_len = flen;
        }

        /* allocate buffer for the string, and
        read the contents of the temporary file */

        if (!(str = (char*) my_malloc(usable_len + 1, MYF(0)))) {
                mutex_exit(&srv_monitor_file_mutex);
                DBUG_RETURN(1);
        }

        rewind(srv_monitor_file);

        if (flen < MAX_STATUS_SIZE) {
                /* Display the entire output. */
                flen = fread(str, 1, flen, srv_monitor_file);
        } else if (trx_list_end < (ulint) flen
                   && trx_list_start < trx_list_end
                   && trx_list_start + (flen - trx_list_end)
                   < MAX_STATUS_SIZE - sizeof truncated_msg - 1) {

                /* Omit the beginning of the list of active transactions. */
                ssize_t len = fread(str, 1, trx_list_start, srv_monitor_file);

                memcpy(str + len, truncated_msg, sizeof truncated_msg - 1);
                len += sizeof truncated_msg - 1;
                usable_len = (MAX_STATUS_SIZE - 1) - len;
                fseek(srv_monitor_file, flen - usable_len, SEEK_SET);
                len += fread(str + len, 1, usable_len, srv_monitor_file);
                flen = len;
        } else {
                /* Omit the end of the output. */
                flen = fread(str, 1, MAX_STATUS_SIZE - 1, srv_monitor_file);
        }

        mutex_exit(&srv_monitor_file_mutex);

        stat_print(thd, innobase_hton_name, (uint) strlen(innobase_hton_name),

        my_free(str);

        DBUG_RETURN(0);
}

参考