Hatena::ブログ(Diary)

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

2018-06-06

Aurora MySQL で DDL を実行してみる

準備

  • データをロードする
$ sysbench /usr/share/sysbench/oltp_read_write.lua \
 --db-driver=mysql \
 --table-size=500000 \
 --mysql-host=aurora01.*********.ap-northeast-1.rds.amazonaws.com \
 --mysql-user=awsuser \
 --mysql-password=********* \
 --mysql-db=mydb \
 --db-ps-mode=disable \
 prepare
mysql> select count(id) from sbtest1;
+-----------+
| count(id) |
+-----------+
|   5000000 |
+-----------+
1 row in set (0.82 sec)

DDL実行

  • カラムを追加する
mysql> alter table sbtest1 add added_col1 char(255);
Query OK, 0 rows affected (53.13 sec)
Records: 0  Duplicates: 0  Warnings: 0
mysql> alter table sbtest1 add added_col2 char(255) default 'abcdefghijklmnopqrstuvwxyz';
Query OK, 0 rows affected (1 min 9.43 sec)
Records: 0  Duplicates: 0  Warnings: 0
  • テーブル定義を確認する
mysql> desc sbtest1;
+------------+-----------+------+-----+----------------------------+----------------+
| Field      | Type      | Null | Key | Default                    | Extra          |
+------------+-----------+------+-----+----------------------------+----------------+
| id         | int(11)   | NO   | PRI | NULL                       | auto_increment |
| k          | int(11)   | NO   | MUL | 0                          |                |
| c          | char(120) | NO   |     |                            |                |
| pad        | char(60)  | NO   |     |                            |                |
| added_col1 | char(255) | YES  |     | NULL                       |                |
| added_col2 | char(255) | YES  |     | abcdefghijklmnopqrstuvwxyz |                |
+------------+-----------+------+-----+----------------------------+----------------+
6 rows in set (0.00 sec)

DML実行

mysql> START TRANSACTION;
Query OK, 0 rows affected (0.00 sec)

mysql> update sbtest1 set added_col1 = '123' where id = 1;
Query OK, 0 rows affected (0.00 sec)
Rows matched: 1  Changed: 0  Warnings: 0

mysql> commit;
Query OK, 0 rows affected (0.01 sec)

参考

2018-05-03

Flask で入力フォームのデータを POST で受け渡す

Flask で入力フォームのデータを POST で受け渡してみた。


メモ


スクリーンショット

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

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


構成

$ tree flask
flask
├── hello.py
└── templates
    ├── confirm.html
    └── form.html

1 directory, 3 files
  • hello.py
from flask import Flask, render_template, request
app = Flask(__name__)

@app.route('/')
def hello():
    name = "Hello World"
    return name

@app.route('/good')
def good():
    name = "Good"
    return name

@app.route('/form')
def form():
   return render_template('form.html')

@app.route('/confirm', methods = ['POST', 'GET'])
def confirm():
   if request.method == 'POST':
      result = request.form
      return render_template("confirm.html",result = result)

if __name__ == "__main__":
    app.run(host='0.0.0.0', debug=True)
  • templates/form.html
<html>
   <body>
      <form action = "/confirm" method = "POST">
         <p>Name <input type = "text" name = "Name" /></p>
         <p>Value <input type ="text" name = "Value" /></p>
         <p><input type = "submit" value = "submit" /></p>
      </form>
   </body>
</html>
  • templates/confirm.html
<html>
   <body>
      <table border = 1>
         {% for key, value in result.iteritems() %}
            <tr>
               <th> {{ key }} </th>
               <td> {{ value }} </td>
            </tr>
         {% endfor %}
      </table>
   </body>
</html>

参考

2018-04-27

MySQL の slow query log を Percona Toolkit の pt-query-digest で整形する

環境

  • macOS Sierra 10.12.6

インストール

% brew install percona-toolkit

使ってみる

  • pt-query-digest で slow query log を集計する。
% pt-query-digest mysql-slowquery.log.2018-04-27.09 > mysql-slowquery.log.2018-04-27.09-pt.txt
mysql-slowquery.log.2018-04-27.09:   9% 04:39 remain
mysql-slowquery.log.2018-04-27.09:  23% 03:16 remain
mysql-slowquery.log.2018-04-27.09:  45% 01:48 remain
mysql-slowquery.log.2018-04-27.09:  72% 00:44 remain
mysql-slowquery.log.2018-04-27.09:  93% 00:10 remain
  • 集計結果を確認する
% less  mysql-slowquery.log.2018-04-27.09-pt.txt
# 150.8s user time, 1.8s system time, 59.41M rss, 2.38G vsz
# Current date: Fri Apr 27 23:28:57 2018
# Hostname: ******
# Files: mysql-slowquery.log.2018-04-27.09
# Overall: 413.58k total, 977 unique, 114.91 QPS, 30.16x concurrency _____
# Time range: 2018-04-27 08:00:02 to 09:00:01
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time        108556s    38us     56s   262ms   640ms   814ms    51ms
# Lock time        129127208518408s       0 18446744073710s 312221233s    30ms 75048244001s    89us
# Rows sent         35.25M       0 169.78k   89.37   28.75   1.61k    0.99
# Rows examine      19.10G       0   9.28M  48.42k  97.04k 279.61k   19.46
# Query size       509.74M      24 742.43k   1.26k   2.38k  21.67k  381.65

# Profile
# Rank Query ID           Response time    Calls  R/Call  V/M   Item
# ==== ================== ================ ====== ======= ===== ==========
#    1 0x959A21D964B0B02E 10676.2713  9.8%   1538  6.9417  1.62 SELECT ...
#    2 0x7D68C5021733113C 10338.2087  9.5%   1537  6.7262  1.57 SELECT ...
#    3 0xF22F26C61E850C7F  9187.9306  8.5%  22197  0.4139  0.03 SELECT ...
#    4 0x864A6BD8BB56F3FC  7608.9758  7.0%  18397  0.4136  0.03 SELECT ....

見方

# 210ms user time, 40ms system time, 26.75M rss, 202.94M vsz
# Current date: Thu Mar 24 18:41:21 2016
# Hostname: xxxx
# Files: /usr/mysql/5.7.11/data/slow.log
# Overall: 119 total, 8 unique, 0 QPS, 0x concurrency ____________________
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          272ms     9us    32ms     2ms     2ms     3ms     2ms
# Lock time           21ms       0     8ms   177us    89us   865us    54us
# Rows sent            510       0     104    4.29       0   19.93       0
# Rows examine         510       0     104    4.29       0   19.93       0
# Query size        17.17k      10     164  147.74  158.58   41.54  158.58

最初のセクションはスローログ全体を俯瞰した様子です。Exec time(スローログ上ではQuery_time), Lock time, Rows sent, Rows examineなど、スローログに書き込まれている情報を集計した情報が書き出されています。

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ===============
#    1 0xCAEC22E79B0EFD3B  0.2041 75.2%   105 0.0019  0.00 INSERT t?
#    2 0x35AAC71503957920  0.0322 11.9%     1 0.0322  0.00 FLUSH
#    3 0x0C922D63DA1D917B  0.0216  8.0%     1 0.0216  0.00 CREATE TABLE t? `t1`
#    4 0x5722277F9D796D79  0.0107  3.9%     2 0.0053  0.01 DROP
# MISC 0xMISC              0.0029  1.1%    10 0.0003   0.0 <4 ITEMS>

次のセクションには、クエリー単位でノーマライズ・集計された結果が並びます。pt-query-digestはスローログを処理する際にリテラルをノーマライズします。column1 = 1やcolumn1 = 2といった数値リテラルはcolumn1 = Nという形に丸められ、同じクエリーとして扱われます(カラム名の数字は丸められないため、数字が入っているカラム名を利用していてもカラムが違えば識別される)。

また、文字列リテラルや行リテラルもノーマライズされますので、個々のクエリーのパラメーターの差異によらずに全体としての傾向を掴めます。このセクションでのクエリーはデフォルトでは「各ノーマライズされたクエリーごとのQuery_timeの和」の降順で並べられています。これは --order-by オプションで変更できます。

Response timeはQuery_timeの和とスローログ全体におけるそのクエリーの占めるパーセンテージが出力されます。Callsはクエリーが実行された回数、R/Callは Response time / Call (平均値)、V/Mは標準偏差です。Itemにはクエリーのサマリーが表示されます。時間がかかっている(R/Callが大きい)クエリーでも稀にしか実行されないものである場合、チューニング対象としてはちょっと不足気味です(たとえば、年に1回しか実行されないクエリーを10秒速くすることにあまり意味はない)。また、時間の累計(Response time)が大きいクエリーである場合でもR/Callが十分小さい場合はスピードアップは困難かも知れません(10秒のクエリーを10%速くすることと、10msのクエリーを10%速くすることでは後者の方が難易度が高い)。

実際のスローログを pt-query-digest に集計させた場合、結果サイズはそれなりに大きくなります。全てを見ていくにも時間がかかりますので、このセクションで目ぼしいクエリーにあたりをつけ、Query ID(ノーマライズされたステートメントから計算されるハッシュ値)を検索する方法がお勧めです。

# Query 1: 0 QPS, 0x concurrency, ID 0xCAEC22E79B0EFD3B at byte 2247 _____
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         88     105
# Exec time     75   204ms     1ms     3ms     2ms     2ms   319us     2ms
# Lock time     32     7ms    37us   589us    64us    76us    57us    54us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size    97  16.75k     160     164  163.33  158.58    0.00  158.58
# String:
# Databases    mysqlslap
# Hosts        localhost
# Time         2016-03-24... (1/0%), 2016-03-24... (1/0%)... 103 more
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `mysqlslap` LIKE 't1'\G
#    SHOW CREATE TABLE `mysqlslap`.`t1`\G
INSERT INTO t1 VALUES (1308044878,'50w46i58Giekxik0cYzfA8BZBLADEg3JhzGfZDoqvQQk0Akcic7lcJInYSsf9wqin6LDC1vzJLkJXKn5onqOy04MTw1WksCYqPl2Jg2eteqOqTLfGCvE4zTZwWvgMz')\G

3つ目のセクションからは、クエリー単位の個別の集計結果が表示されます。1行目にQuery IDが含まれているため、2つ目のセクションで表示されていたQuery IDを検索すると個別クエリーのセクションの先頭行に行けるようになっています。

筆者はここで Rows examine / Rows sent の値をよく計算します。GROUP BYを使っている場合を除けばRows examine / Rows sentの値が1に近い(小さい)ほど効率良くインデックスで WHERE 句を処理できているからです。1に近いほどインデックス以外の箇所でSQLをチューニングしなければならないため時間がかかり、1から遠いほどインデックスの追加で劇的に速くなる可能性があるため、効率良くチューニングできる可能性が高まります。

またRows sentやRows examine、Exec timeに大きなバラつきがあり相関しているように見える場合、WHERE句の条件によって結果セットの大きさが大幅に変化していることが考えられます。転送された結果セットが本当に全てアプリケーション側で利用されているかを確認すると良いでしょう(本当に使われていた場合はどうしようもないが)。

Rows sent、Rows examine、Lock timeにバラつきが少ないにも関わらずExec timeにバラつきがある場合は、バッファプールのヒット率が悪いことなどが考えられます(MyISAMストレージエンジンのテーブルであればこの限りではない)。InnoDBバッファプールはSELECTのみでなくINSERTやDELETEの際にも利用されます。またInnoDBのテーブル圧縮を使用している場合、バッファプールミスヒットのコストは無圧縮状態に比べて非常に高くなるため注意が必要です。バッファプールの他にもテーブルキャッシュが足りなくなっていないかなども考慮する必要があります。

Timeの行は本来であれば「そのクエリーが最初に現れた時間」と「そのクエリーが最後に現れた時間」を表示しますが、残念ながらMySQL 5.7系列のスローログには対応していません。バッチなどによる一過性のスローログなのか、継続的なものか、あるいはもう既に修正されたもの(最後に現れた時間が十分過去)なのかをチェックしておきましょう。

最後の行は、このチェックサムのクエリーのうちサンプルとして1件、ノーマライズしていないクエリーを表示します。EXPLAINや実際に実行する時にそのままコピー&ペーストできます。

スローログの集計に便利な「pt-query-digest」を使ってみよう | Think IT(シンクイット)

参考

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、ALTERDROP など) がログに記録されるようにすることもできます。さらに、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