Hatena::ブログ(Diary)

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

2018-07-16

Amazon Redshift に重いクエリを同時多重実行しながら性能情報を見る

Redshift に負荷をかける

EC2gitpsql、pgbench をインストールする
$ sudo yum -y install postgresql96
$ sudo yum -y install postgresql96-contrib
$ sudo yum -y install git
Redshift で負荷かけの準備を行う
  • EC2 から Redshift にスーパーユーザーで接続する
$ psql "host=ds28xl4n.******.us-west-2.redshift.amazonaws.com user=awsuser dbname=mydb port=5439"
  • ベンチマーク用のグループとユーザーを作成する
    • キューの同時実行数を超えると情報取得クエリもキューで待たされるため、負荷かけ実行ユーザーを別に作成してキューを分ける
# create group bench;
# create user benchuser password '********' in group bench;
# ALTER USER benchuser SET enable_result_cache_for_session = off;
# \q
$ psql "host=ds28xl4n.******.us-west-2.redshift.amazonaws.com user=benchuser dbname=mydb port=5439"
  • テーブルを作成する
# CREATE TABLE lineorder 
(
  lo_orderkey          INTEGER NOT NULL,
  lo_linenumber        INTEGER NOT NULL,
  lo_custkey           INTEGER NOT NULL,
  lo_partkey           INTEGER NOT NULL,
  lo_suppkey           INTEGER NOT NULL,
  lo_orderdate         INTEGER NOT NULL,
  lo_orderpriority     VARCHAR(15) NOT NULL,
  lo_shippriority      VARCHAR(1) NOT NULL,
  lo_quantity          INTEGER NOT NULL,
  lo_extendedprice     INTEGER NOT NULL,
  lo_ordertotalprice   INTEGER NOT NULL,
  lo_discount          INTEGER NOT NULL,
  lo_revenue           INTEGER NOT NULL,
  lo_supplycost        INTEGER NOT NULL,
  lo_tax               INTEGER NOT NULL,
  lo_commitdate        INTEGER NOT NULL,
  lo_shipmode          VARCHAR(10) NOT NULL
);
  • データをロードする
# copy lineorder from 's3://awssampledbuswest2/ssbgz/lineorder' 
credentials 'aws_access_key_id=<Your-Access-Key-ID>;aws_secret_access_key=<Your-Secret-Access-Key>'
gzip compupdate off region 'us-west-2';
# \q
Redshift に pgbench で負荷をかける
  • lineorder.sql を作成する
$ cat << EOF > lineorder.sql
select count(a.*) from lineorder a, lineorder b;
EOF
  • pgbench で lineorder.sql を10並列で合計50回実行する
$ pgbench -r -c 10 -j 10 -n -t 50 -f lineorder.sql -U awsuser -h ds28xl4n.******.us-west-2.redshift.amazonaws.com -d mydb -p 5439

性能情報の見え方

マネジメントコンソール
システムテーブル・システムビュー
  • スーパーユーザーでログインする(全ユーザーの情報を見るため)
$ psql "host=ds28xl4n.******.us-west-2.redshift.amazonaws.com user=awsuser dbname=mydb port=5439"
  • running_queues.sql でキュー待ちと実行中のクエリを確認する
    • state が Queue だとキュー待ち、Run だと実行中。q_sec がキュー待ち時間(秒)、exe_sec が実行時間(秒)。
    • CPU時間(cpu_sec)が exe_sec より長いことがあるのはクエリマルチプロセッサで並列実行された時間の合計のためと思われる。
    • read_mb はディスク読込み量、spill_mb はディスク書込み量。
ds28xl4n-r awsuser 00:10 =# \i running_queues.sql
   user    |  pid  |  xid   | query | q | slt |        start        | state | q_sec | exe_sec | cpu_sec | read_mb | spill_mb | ret_rows |    nl_rows     |                                            sql                                             | alert
-----------+-------+--------+-------+---+-----+---------------------+-------+-------+---------+---------+---------+----------+----------+----------------+--------------------------------------------------------------------------------------------+-------
 benchuser | 34229 | 762470 | 89556 | 6 |   1 | 2018-07-16 21:39:43 | Run   |     0 |    9074 |  267373 |     128 |          |          | 37471050468695 | select count(a.*) from lineorder a, lineorder b;                                           | NL
 benchuser | 34230 | 762472 | 89557 | 6 |   1 | 2018-07-16 21:39:43 | Run   |     0 |    9074 |  253425 |     128 |          |          | 35415740526019 | select count(a.*) from lineorder a, lineorder b;                                           | NL
 benchuser | 34231 | 762474 | 89558 | 6 |   1 | 2018-07-16 21:39:43 | Run   |     0 |    9074 |  274471 |     128 |          |          | 38407248173760 | select count(a.*) from lineorder a, lineorder b;                                           | NL
 benchuser | 34228 | 762476 | 89559 | 6 |   1 | 2018-07-16 21:39:43 | Run   |     0 |    9074 |  255883 |     128 |          |          | 35736062097462 | select count(a.*) from lineorder a, lineorder b;                                           | NL
 benchuser | 34232 | 762478 | 89560 | 6 |   1 | 2018-07-16 21:39:43 | Run   |     0 |    9074 |  250486 |     128 |          |          | 34941414838224 | select count(a.*) from lineorder a, lineorder b;                                           | NL
 benchuser | 34233 | 762480 | 89561 | 6 |   1 | 2018-07-16 21:39:43 | Queue |  9074 |       0 |         |         |          |          |                | select count(a.*) from lineorder a, lineorder b;                                           |
 benchuser | 34235 | 762482 | 89562 | 6 |   1 | 2018-07-16 21:39:43 | Queue |  9074 |       0 |         |         |          |          |                | select count(a.*) from lineorder a, lineorder b;                                           |
 benchuser | 34234 | 762484 | 89563 | 6 |   1 | 2018-07-16 21:39:43 | Queue |  9074 |       0 |         |         |          |          |                | select count(a.*) from lineorder a, lineorder b;                                           |
 benchuser | 34236 | 762486 | 89564 | 6 |   1 | 2018-07-16 21:39:43 | Queue |  9074 |       0 |         |         |          |          |                | select count(a.*) from lineorder a, lineorder b;                                           |
 benchuser | 34237 | 762487 | 89565 | 6 |   1 | 2018-07-16 21:39:43 | Queue |  9074 |       0 |         |         |          |          |                | select count(a.*) from lineorder a, lineorder b;                                           |
 awsuser   | 34063 | 765301 | 90186 | 7 |   1 | 2018-07-17 00:10:57 | Run   |     0 |       0 |       0 |       0 |          |          |                | /***************************************************************************************** |
(11 rows)

Time: 1024.246 ms
  • lock_wait.sql でロック待ち状況を確認する
    • objectname が対象オブジェクト、mode がロックモード、txn_start がトランザクション開始時刻。
    • block_sec、block_min、block_hr はロックを保持している秒、分、時間。
    • waiting はロック待ち時間(秒)。
    • num_blockingは待たされているセッション数、pidlist は待たされているセッションの pid。
ds28xl4n-r awsuser 21:42 =# \i lock_wait.sql
  xid   |  pid  | username  | dbname | relation | schemaname | objectname |      mode       | granted | obj_type |         txn_start          | block_sec | block_min | block_hr | waiting | max_sec_blocking | num_blocking | pidlist
--------+-------+-----------+--------+----------+------------+------------+-----------------+---------+----------+----------------------------+-----------+-----------+----------+---------+------------------+--------------+---------
 762484 | 34234 | benchuser | mydb   |   153654 | public     | lineorder  | AccessShareLock | True    | relation | 2018-07-16 21:39:43.911033 |    197.83 |       3.3 |     0.05 |         |                  |              |
 762478 | 34232 | benchuser | mydb   |   153654 | public     | lineorder  | AccessShareLock | True    | relation | 2018-07-16 21:39:43.905794 |    197.83 |       3.3 |     0.05 |         |                  |              |
 762482 | 34235 | benchuser | mydb   |   153654 | public     | lineorder  | AccessShareLock | True    | relation | 2018-07-16 21:39:43.909771 |    197.83 |       3.3 |     0.05 |         |                  |              |
 762474 | 34231 | benchuser | mydb   |   153654 | public     | lineorder  | AccessShareLock | True    | relation | 2018-07-16 21:39:43.90356  |    197.83 |       3.3 |     0.05 |         |                  |              |
 762476 | 34228 | benchuser | mydb   |   153654 | public     | lineorder  | AccessShareLock | True    | relation | 2018-07-16 21:39:43.904795 |    197.83 |       3.3 |     0.05 |         |                  |              |
 762486 | 34236 | benchuser | mydb   |   153654 | public     | lineorder  | AccessShareLock | True    | relation | 2018-07-16 21:39:43.912798 |    197.83 |       3.3 |     0.05 |         |                  |              |
 762480 | 34233 | benchuser | mydb   |   153654 | public     | lineorder  | AccessShareLock | True    | relation | 2018-07-16 21:39:43.907442 |    197.83 |       3.3 |     0.05 |         |                  |              |
 762487 | 34237 | benchuser | mydb   |   153654 | public     | lineorder  | AccessShareLock | True    | relation | 2018-07-16 21:39:43.914389 |    197.83 |       3.3 |     0.05 |         |                  |              |
 762470 | 34229 | benchuser | mydb   |   153654 | public     | lineorder  | AccessShareLock | True    | relation | 2018-07-16 21:39:43.900309 |    197.83 |       3.3 |     0.05 |         |                  |              |
 762472 | 34230 | benchuser | mydb   |   153654 | public     | lineorder  | AccessShareLock | True    | relation | 2018-07-16 21:39:43.90117  |    197.83 |       3.3 |     0.05 |         |                  |              |
(10 rows)

Time: 40773.823 ms
  • top_queries.sql で実行時間の長いクエリを調べる
    • クエリテキストで集計した実行時間の長いトップ50が表示される。
    • n_qry が実行回数、min/max/avg が実行時間の最小/最大/平均で total が実行時間の合計。
    • max_query_id がクエリIDが最大のもので、last_run がクエリが最後に実行された日付。
ds28xl4n-r awsuser 00:48 =# \i top_queries.sql
  db  | n_qry |                                     qrytext                                      |   min   |   max   |   avg   |  total  | max_query_id |  last_run  | aborted |    event
------+-------+----------------------------------------------------------------------------------+---------+---------+---------+---------+--------------+------------+---------+-------------
 mydb |     1 | select count(a.*) from lineorder a, lineorder b;                                 | 1603.00 | 1603.00 | 1603.00 | 1603.00 |        80506 | 2018-07-16 |       1 | Nested Loop
 mydb |     1 | select * from STV_EXEC_STATE ORDER BY segment, step, slice;                      |  305.00 |  305.00 |  305.00 |  305.00 |        80640 | 2018-07-16 |       0 |
 mydb |     1 | copy lineorder from 's3://awssampledbuswest2/ssbgz/lineorder' credentials '' gzi |  179.00 |  179.00 |  179.00 |  179.00 |        85025 | 2018-07-16 |       0 |
 mydb |     1 | /******************************************************************************* |  100.00 |  100.00 |  100.00 |  100.00 |        89635 | 2018-07-16 |       0 | Nested Loop
 mydb |     1 | select * from lineorder;                                                         |   53.00 |   53.00 |   53.00 |   53.00 |        89549 | 2018-07-16 |       1 |
 mydb |     1 | /******************************************************************************* |   50.00 |   50.00 |   50.00 |   50.00 |        89648 | 2018-07-16 |       0 |
 mydb |     2 | /******************************************************************************* |    2.00 |   46.00 |   24.00 |   48.00 |        90184 | 2018-07-17 |       0 |
 mydb |     1 | /******************************************************************************* |   41.00 |   41.00 |   41.00 |   41.00 |        89582 | 2018-07-16 |       0 |
 mydb |     5 | select trim(u.usename) as user, s.pid, q.xid,q.query,q.service_class as "q", q.s |    1.00 |   29.00 |    6.60 |   33.00 |        87441 | 2018-07-16 |       0 |
 mydb |     1 | /******************************************************************************* |   20.00 |   20.00 |   20.00 |   20.00 |        89626 | 2018-07-16 |       0 |
 mydb |     1 | /******************************************************************************* |   20.00 |   20.00 |   20.00 |   20.00 |        89610 | 2018-07-16 |       0 |
 mydb |     1 | select * from SVL_QUERY_QUEUE_INFO;                                              |   17.00 |   17.00 |   17.00 |   17.00 |        85321 | 2018-07-16 |       0 |
 mydb |     1 | select * from SVL_QUERY_REPORT;                                                  |   17.00 |   17.00 |   17.00 |   17.00 |        82789 | 2018-07-16 |       1 |
 mydb |     1 | select trim(database) as DB, count(query) as n_qry, max(substring (qrytext,1,80) |   15.00 |   15.00 |   15.00 |   15.00 |        82847 | 2018-07-16 |       0 |
 mydb |     1 | select * from admin.v_check_wlm_query_time;                                      |   12.00 |   12.00 |   12.00 |   12.00 |        85257 | 2018-07-16 |       0 |
 mydb |     2 | SELECT w.query ,substring(q.querytxt,1,100) AS querytxt ,w.queue_start_time ,w.s |    0.00 |   11.00 |    5.50 |   11.00 |        85266 | 2018-07-16 |       0 |
 mydb |     1 | select * from SVV_QUERY_STATE;                                                   |   11.00 |   11.00 |   11.00 |   11.00 |        82820 | 2018-07-16 |       0 |
 mydb |     1 | SELECT date_trunc('hour',a.service_class_start_time) AS hour, a.service_class, b |   10.00 |   10.00 |   10.00 |   10.00 |        89658 | 2018-07-16 |       0 |
 mydb |     6 | /******************************************************************************* |    1.00 |    1.00 |    1.00 |    6.00 |        90186 | 2018-07-17 |       0 |
 mydb |     1 | SELECT *, DATEDIFF(SEC,STARTTIME,ENDTIME) AS DATEDIFF FROM STL_QUERY WHERE QUERY |    6.00 |    6.00 |    6.00 |    6.00 |        82812 | 2018-07-16 |       0 |
 mydb |     1 | SELECT s.process AS pid ,date_Trunc ('second',s.starttime) AS S_START ,datediff( |    6.00 |    6.00 |    6.00 |    6.00 |        82831 | 2018-07-16 |       0 |
 mydb |     1 | /******************************************************************************* |    6.00 |    6.00 |    6.00 |    6.00 |        89606 | 2018-07-16 |       0 |
 mydb |     2 | select * from STV_EXEC_STATE ;                                                   |    0.00 |    5.00 |    2.50 |    5.00 |        82795 | 2018-07-16 |       0 |
 mydb |     1 | select * from stl_query;                                                         |    5.00 |    5.00 |    5.00 |    5.00 |        82816 | 2018-07-16 |       0 |
 mydb |     1 | padb_fetch_sample: select * from lineorder                                       |    5.00 |    5.00 |    5.00 |    5.00 |        85039 | 2018-07-16 |       0 | Filter
 mydb |    50 | select count(1) from lineorder;                                                  |    0.00 |    2.00 |    0.08 |    4.00 |        80493 | 2018-07-16 |       0 |
 mydb |     2 | /* query showing queries which are waiting on a WLM Query Slot */ SELECT w.query |    0.00 |    1.00 |    0.50 |    1.00 |        90180 | 2018-07-17 |       0 |
 mydb |     1 | select * from STV_INFLIGHT;                                                      |    1.00 |    1.00 |    1.00 |    1.00 |        82788 | 2018-07-16 |       0 |
 mydb |     1 | SELECT TRIM(DATABASE) AS DB, w.query, SUBSTRING(q.querytxt,1,100) AS querytxt, w |    1.00 |    1.00 |    1.00 |    1.00 |        89655 | 2018-07-16 |       0 |
 mydb |     1 | /******************************************************************************* |    1.00 |    1.00 |    1.00 |    1.00 |        89597 | 2018-07-16 |       0 |
 mydb |     4 | select * from stv_wlm_query_state;                                               |    0.00 |    1.00 |    0.25 |    1.00 |        87438 | 2018-07-16 |       0 |
 mydb |     1 | select count(*) from lineorder;                                                  |    0.00 |    0.00 |    0.00 |    0.00 |        89553 | 2018-07-16 |       0 |
 mydb |     1 | /* Query showing information about sessions with currently running queries */ SE |    0.00 |    0.00 |    0.00 |    0.00 |        89592 | 2018-07-16 |       0 |
(33 rows)

Time: 531.186 ms
  • top_queries_and_cursors.sql で実行時間の長いクエリを調べる
    • クエリテキストで集計した実行時間の長いトップ50が表示される。
    • top_queries.sql と似ているが、CPU時間(cpu)、CPU使用率(cpupct)、ディスク読込み量(mb_read)、一時領域使用量(spill)など情報量が多い。
ds28xl4n-r awsuser 00:58 =# \i top_queries_and_cursors.sql
  db  | n_qry |                                                         qrytext                                                          |   max   |   avg   |  total  | queue |  cpu  | cpupct | spill | mb_read | rows_ret | max_query |  last_run  | aborted | alert
------+-------+--------------------------------------------------------------------------------------------------------------------------+---------+---------+---------+-------+-------+--------+-------+---------+----------+-----------+------------+---------+-------
 mydb |     1 | select count(a.*) from lineorder a, lineorder b;                                                                         | 1603.00 | 1603.00 | 1603.00 |     6 | 64935 |  63.29 |       |     128 |          |     80506 | 2018-07-16 |       1 | NL
 mydb |     1 | select * from STV_EXEC_STATE ORDER BY segment, step, slice;                                                              |  305.00 |  305.00 |  305.00 |       |       |        |       |         |          |     80640 | 2018-07-16 |       0 |
 mydb |     1 | copy lineorder from 's3://awssampledbuswest2/ssbgz/lineorder' credentials '' gzip compupdate off region 'us-west-2';     |  179.00 |  179.00 |  179.00 |     6 |  1809 |  14.42 |       |       0 |          |     85025 | 2018-07-16 |       0 |
 mydb |     1 | /********************************************************************************************** Purpose: Returns the hig |  100.00 |  100.00 |  100.00 |     7 |   122 |   7.24 |       |       0 |          |     89635 | 2018-07-16 |       0 | NL
 mydb |     1 | /********************************************************************************************** Purpose: Return Alerts f |   68.00 |   68.00 |   68.00 |     7 |    17 |  20.58 |       |       0 |          |     90369 | 2018-07-17 |       0 | NL
 mydb |     2 | /********************************************************************************************** WLM QMR Rule Candidates  |   50.00 |   28.50 |   57.00 |     7 |     1 |   0.05 |       |       0 |          |     90365 | 2018-07-17 |       0 |
 mydb |     1 | select * from lineorder;                                                                                                 |   53.00 |   53.00 |   53.00 |     7 |    56 |   1.74 |       |    1850 | 23561221 |     89549 | 2018-07-16 |       1 |
 mydb |     2 | /********************************************************************************************** Purpose: Returns the per |   46.00 |   24.00 |   48.00 |     7 |       |        |       |       0 |          |     90184 | 2018-07-17 |       0 |
 mydb |     1 | /********************************************************************************************** Purpose: Return instance |   41.00 |   41.00 |   41.00 |     7 |       |        |       |       0 |          |     89582 | 2018-07-16 |       0 |
 mydb |     3 | select trim(u.usename) as user, s.pid, q.xid,q.query,q.service_class as "q", q.slot_count as slt, date_trunc('second',q. |   29.00 |   10.33 |   31.00 |     6 |     1 |   0.37 |       |       0 |          |     82846 | 2018-07-16 |       0 |
 mydb |     1 | /********************************************************************************************** Purpose: Return the top  |   20.00 |   20.00 |   20.00 |     7 |       |        |       |       0 |          |     89626 | 2018-07-16 |       0 |
 mydb |     1 | /********************************************************************************************** Purpose: Return instance |   20.00 |   20.00 |   20.00 |     7 |    18 |  22.67 |       |       0 |          |     89610 | 2018-07-16 |       0 |
 mydb |     1 | select * from SVL_QUERY_QUEUE_INFO;                                                                                      |   17.00 |   17.00 |   17.00 |     7 |       |        |       |       0 |          |     85321 | 2018-07-16 |       0 |
 mydb |     1 | select * from SVL_QUERY_REPORT;                                                                                          |   17.00 |   17.00 |   17.00 |       |       |        |       |         |          |     82789 | 2018-07-16 |       1 |
 mydb |     1 | select trim(database) as DB, count(query) as n_qry, max(substring (qrytext,1,80)) as qrytext, min(run_seconds) as "min"  |   15.00 |   15.00 |   15.00 |     6 |       |        |       |       0 |          |     82847 | 2018-07-16 |       0 |
 mydb |     1 | select * from admin.v_check_wlm_query_time;                                                                              |   12.00 |   12.00 |   12.00 |       |       |        |       |         |          |     85257 | 2018-07-16 |       0 |
 mydb |     1 | select * from SVV_QUERY_STATE;                                                                                           |   11.00 |   11.00 |   11.00 |     6 |       |        |       |       0 |          |     82820 | 2018-07-16 |       0 |
 mydb |     1 | SELECT w.query ,substring(q.querytxt,1,100) AS querytxt ,w.queue_start_time ,w.service_class AS class ,w.slot_count AS s |   11.00 |   11.00 |   11.00 |     6 |       |        |       |       0 |          |     82837 | 2018-07-16 |       0 |
 mydb |     1 | SELECT date_trunc('hour',a.service_class_start_time) AS hour, a.service_class, b.condition AS service_class_condition, C |   10.00 |   10.00 |   10.00 |     7 |       |        |       |         |      202 |     89658 | 2018-07-16 |       0 |
 mydb |     1 | SELECT *, DATEDIFF(SEC,STARTTIME,ENDTIME) AS DATEDIFF FROM STL_QUERY WHERE QUERYTXT LIKE 'SELECT * FROM%' ORDER BY START |    6.00 |    6.00 |    6.00 |       |       |        |       |         |          |     82812 | 2018-07-16 |       0 |
 mydb |     6 | /********************************************************************************************** Purpose: Return the Curr |    1.00 |    1.00 |    6.00 |     7 |     1 |   0.41 |       |       0 |          |     90186 | 2018-07-17 |       0 |
 mydb |     1 | /********************************************************************************************** Purpose: Return commit q |    6.00 |    6.00 |    6.00 |     7 |       |        |       |       0 |          |     89606 | 2018-07-16 |       0 |
 mydb |     1 | SELECT s.process AS pid ,date_Trunc ('second',s.starttime) AS S_START ,datediff(minutes,s.starttime,getdate ()) AS conn_ |    6.00 |    6.00 |    6.00 |       |       |        |       |         |          |     82831 | 2018-07-16 |       0 |
 mydb |     2 | select * from STV_EXEC_STATE ;                                                                                           |    5.00 |    2.50 |    5.00 |       |       |        |       |         |          |     82795 | 2018-07-16 |       0 |
 mydb |     1 | padb_fetch_sample: select * from lineorder                                                                               |    5.00 |    5.00 |    5.00 |     6 |   136 |  98.42 |       |   25890 |          |     85039 | 2018-07-16 |       0 |
 mydb |     1 | select * from stl_query;                                                                                                 |    5.00 |    5.00 |    5.00 |       |       |        |       |         |          |     82816 | 2018-07-16 |       0 |
 mydb |    50 | select count(1) from lineorder;                                                                                          |    2.00 |    0.08 |    4.00 |     6 |     1 |  85.02 |       |      20 |          |     80493 | 2018-07-16 |       0 |
 mydb |     2 | select trim(u.usename) as user, s.pid, q.xid,q.query,q.service_class as "q", q.slot_count as slt, date_trunc('second',q. |    1.00 |    1.00 |    2.00 |     7 |       |        |       |       0 |          |     87441 | 2018-07-16 |       0 |
 mydb |     2 | /********************************************************************************************** Purpose: Return the top  |    1.00 |    1.00 |    2.00 |     7 |       |        |       |       0 |          |     90337 | 2018-07-17 |       0 |
 mydb |     1 | SELECT TRIM(DATABASE) AS DB, w.query, SUBSTRING(q.querytxt,1,100) AS querytxt, w.queue_start_time, w.service_class AS cl |    1.00 |    1.00 |    1.00 |       |       |        |       |         |          |     89655 | 2018-07-16 |       0 |
 mydb |     1 | select * from STV_INFLIGHT;                                                                                              |    1.00 |    1.00 |    1.00 |       |       |        |       |         |          |     82788 | 2018-07-16 |       0 |
 mydb |     2 | /* query showing queries which are waiting on a WLM Query Slot */ SELECT w.query ,substring(q.querytxt,1,100) AS querytx |    1.00 |    0.50 |    1.00 |     7 |     1 |   0.23 |       |       0 |          |     90180 | 2018-07-17 |       0 |
 mydb |     4 | select * from stv_wlm_query_state;                                                                                       |    1.00 |    0.25 |    1.00 |       |       |        |       |         |          |     87438 | 2018-07-16 |       0 |
 mydb |     1 | SELECT w.query ,substring(q.querytxt,1,100) AS querytxt ,w.queue_start_time ,w.service_class AS class ,w.slot_count AS s |    0.00 |    0.00 |    0.00 |     7 |     1 |   1.70 |       |       0 |          |     85266 | 2018-07-16 |       0 |
 mydb |     1 | select count(*) from lineorder;                                                                                          |    0.00 |    0.00 |    0.00 |       |       |        |       |         |          |     89553 | 2018-07-16 |       0 |
 mydb |     1 | /* Query showing information about sessions with currently running queries */ SELECT s.process AS pid ,date_Trunc ('seco |    0.00 |    0.00 |    0.00 |       |       |        |       |         |          |     89592 | 2018-07-16 |       0 |
(36 rows)

Time: 1141.186 ms
# select a.userid, a.query, a.total_queue_time, a.total_exec_time, a.exec_start_time, a.exec_end_time, substring(b.text,1,100)
from stl_wlm_query a, stl_querytext b
where a.query = b.query
order by a.total_exec_time desc
limit 10;

 userid | query | total_queue_time | total_exec_time |      exec_start_time       |       exec_end_time        |                                              substring
--------+-------+------------------+-----------------+----------------------------+----------------------------+------------------------------------------------------------------------------------------------------
    100 | 80506 |                0 |      1602831743 | 2018-07-16 18:51:06.926251 | 2018-07-16 19:17:49.757994 | select count(a.*) from lineorder a, lineorder b;
    102 | 85025 |                0 |       179448651 | 2018-07-16 20:12:48.089068 | 2018-07-16 20:15:47.537719 | copy lineorder from 's3://awssampledbuswest2/ssbgz/lineorder'\ncredentials ''\ngzip compupdate off r
    100 | 89635 |                0 |        99895758 | 2018-07-16 21:54:04.487489 | 2018-07-16 21:55:44.383247 | /**********************************************************************************************\nPur
    100 | 89635 |                0 |        99895758 | 2018-07-16 21:54:04.487489 | 2018-07-16 21:55:44.383247 |  results can be used to fine tune WLM queues which contain too many or too few slots\nresulting in W
    100 | 89635 |                0 |        99895758 | 2018-07-16 21:54:04.487489 | 2018-07-16 21:55:44.383247 |  in the WLM configuration file.\nmax_wlm_concurrency: Current actual concurrency level of the servic
    100 | 89635 |                0 |        99895758 | 2018-07-16 21:54:04.487489 | 2018-07-16 21:55:44.383247 | time.\nmax_slots_ts: Most recent time at which the max_service_class_slots occurred.\nlast_queued_ti
    100 | 89635 |                0 |        99895758 | 2018-07-16 21:54:04.487489 | 2018-07-16 21:55:44.383247 | Since generate_series is unsupported in Redshift, this uses an unelegant method to generate a dt\nse
    100 | 89635 |                0 |        99895758 | 2018-07-16 21:54:04.487489 | 2018-07-16 21:55:44.383247 | .\n- If SVL_QUERY_REPORT has < 604800 rows you may want to substitue SVL_QUERY_REPORT for another ta
    100 | 89635 |                0 |        99895758 | 2018-07-16 21:54:04.487489 | 2018-07-16 21:55:44.383247 | un after period of heaviest query activity\nHistory:\n2015-08-31 chriz-bigdata created\n************
    100 | 89635 |                0 |        99895758 | 2018-07-16 21:54:04.487489 | 2018-07-16 21:55:44.383247 | dt_series AS (select sysdate - (n * interval '1 second') as dt from (select row_number() over () as
(10 rows)

Time: 258.192 ms
# select a.userid, a.query, a.total_queue_time, a.total_exec_time, a.queue_start_time, a.queue_end_time, substring(b.text,1,100)
from stl_wlm_query a, stl_querytext b
where a.query = b.query
order by a.total_queue_time desc
limit 10;

 userid | query | total_queue_time | total_exec_time |      queue_start_time      |       queue_end_time       |                                              substring
--------+-------+------------------+-----------------+----------------------------+----------------------------+------------------------------------------------------------------------------------------------------
    100 | 80640 |        304428952 |               0 | 2018-07-16 19:20:38.746379 | 2018-07-16 19:25:43.175331 | select * from STV_EXEC_STATE ORDER BY segment, step, slice;
      1 | 79172 |                0 |          103599 | 2018-07-16 13:40:59.910911 | 2018-07-16 13:40:59.910911 | elect oid from pg_namespace where nspname='pg_internal'))
      1 | 79212 |                0 |           97704 | 2018-07-16 13:51:59.913595 | 2018-07-16 13:51:59.913595 | select count(distinct id) from pg_catalog.stv_tbl_perm where temp = false and db_id > 1 and id not i
      1 | 79220 |                0 |           17152 | 2018-07-16 13:53:00.02343  | 2018-07-16 13:53:00.02343  | select node_num,value from stv_fdisk_stats where name='blocks_allocated_total'
      1 | 79307 |                0 |           20577 | 2018-07-16 14:16:39.938937 | 2018-07-16 14:16:39.938937 | select sum(value) from stv_fdisk_stats where name = 'blocks_allocated_permanent'
      1 | 79267 |                0 |           96503 | 2018-07-16 14:05:59.917467 | 2018-07-16 14:05:59.917467 | elect oid from pg_namespace where nspname='pg_internal'))
      1 | 79259 |                0 |           94293 | 2018-07-16 14:03:11.801154 | 2018-07-16 14:03:11.801154 | elect oid from pg_namespace where nspname='pg_internal'))
      1 | 79314 |                0 |            6204 | 2018-07-16 14:17:48.023831 | 2018-07-16 14:17:48.023831 | Select * from pg_internal.redshift_auto_health_check_386769
      1 | 79493 |                0 |           16171 | 2018-07-16 15:02:00.041758 | 2018-07-16 15:02:00.041758 | select node_num,value from stv_fdisk_stats where name='blocks_allocated_total'
      1 | 79360 |                0 |            6354 | 2018-07-16 14:28:48.186254 | 2018-07-16 14:28:48.186254 | Select * from pg_internal.redshift_auto_health_check_386769
Time: 4216.293 ms

2018-06-10

MySQL の InnoDB テーブルの統計情報を確認する

MySQLInnoDB テーブルにどんな統計情報があるのか調べてみた。MySQL 5.6 にはテーブル統計インデックス統計だけで、MySQL 8.0 からヒストグラム*1が入るらしい。


  • テーブル定義
mysql> desc mydb.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   |     |         |                |
+-------+-----------+------+-----+---------+----------------+
4 rows in set (0.00 sec)
mysql> select * from mysql.innodb_table_stats where table_name = 'sbtest1';
+---------------+------------+---------------------+--------+----------------------+--------------------------+
| database_name | table_name | last_update         | n_rows | clustered_index_size | sum_of_other_index_sizes |
+---------------+------------+---------------------+--------+----------------------+--------------------------+
| mydb          | sbtest1    | 2018-06-10 20:39:25 |      1 |                    1 |                        1 |
+---------------+------------+---------------------+--------+----------------------+--------------------------+
1 row in set (0.00 sec)
mysql> select * from mysql.innodb_index_stats where table_name = 'sbtest1';
+---------------+------------+------------+---------------------+--------------+------------+-------------+-----------------------------------+
| database_name | table_name | index_name | last_update         | stat_name    | stat_value | sample_size | stat_description                  |
+---------------+------------+------------+---------------------+--------------+------------+-------------+-----------------------------------+
| mydb          | sbtest1    | PRIMARY    | 2018-06-10 20:39:25 | n_diff_pfx01 |          1 |           1 | id                                |
| mydb          | sbtest1    | PRIMARY    | 2018-06-10 20:39:25 | n_leaf_pages |          1 |        NULL | Number of leaf pages in the index |
| mydb          | sbtest1    | PRIMARY    | 2018-06-10 20:39:25 | size         |          1 |        NULL | Number of pages in the index      |
| mydb          | sbtest1    | k_1        | 2018-06-10 20:39:25 | n_diff_pfx01 |          1 |           1 | k                                 |
| mydb          | sbtest1    | k_1        | 2018-06-10 20:39:25 | n_diff_pfx02 |          1 |           1 | k,id                              |
| mydb          | sbtest1    | k_1        | 2018-06-10 20:39:25 | n_leaf_pages |          1 |        NULL | Number of leaf pages in the index |
| mydb          | sbtest1    | k_1        | 2018-06-10 20:39:25 | size         |          1 |        NULL | Number of pages in the index      |
+---------------+------------+------------+---------------------+--------------+------------+-------------+-----------------------------------+
7 rows in set (0.00 sec)

参考

一体いつ変わったのかリリースノートにも全然書いてないんだけど、 mysql.column_statistics に名前が変わってシステムテーブルとして直接参照が不可能に、中身を覗くには information_schema.column_statistics に名前が変わっていた。

日々の覚書: MySQL 8.0.0でついにヒストグラムがサポートされるらしい(が、自動で統計してくれるわけではない様子)

*1Oracle Database で言う列統計ヒストグラム

2018-05-03

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

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


メモ

  • Flaskのデフォルトのテンプレートエンジンは jinja2 で HTML と Python のコードを同居させることができる。
  • テンプレートはアプリケーションルート配下の templtates ディレクトリ以下に置く。

スクリーンショット

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>

参考

psycopg2 で Pyhton から PostgreSQL に接続する

インストール

$ sudo pip install psycopg2
$ sudo pip install psycopg2-binary

サンプルコード

  • psycopg2_sample.py
import psycopg2
conn = psycopg2.connect("host=aurora-postgres-r42xl.******.ap-northeast-1.rds.amazonaws.com user=awsuser dbname=mydb  port=5432 password=******")
cur = conn.cursor()
cur.execute("DROP TABLE test;")
cur.execute("CREATE TABLE test (id serial PRIMARY KEY, num integer, data varchar);")
cur.execute("INSERT INTO test (num, data) VALUES (%s, %s)", (100, "abc'def"))
cur.execute("SELECT * FROM test;")
row = cur.fetchone()
print(row)
conn.commit()
cur.close()
conn.close()

実行結果

$ python psycopg2_sample.py
(1, 100, "abc'def")


補足

$ python psycopg2_sample.py
/usr/local/lib64/python2.7/site-packages/psycopg2/__init__.py:144: UserWarning: The psycopg2 wheel package will be renamed from release 2.8; in order to keep installing from binary please use "pip install psycopg2-binary" instead. For details see: <http://initd.org/psycopg/docs/install.html#binary-install-from-pypi>.
  """)

と怒られたので、

$ sudo pip install psycopg2-binary

psycopg2-binary をインストールした。


参考

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

Oracle Database の DBMS_RANDOM.VALUE を MySQL 向けに書き換える

Oracle Database の以下の PL/SQL コードを

standard_price := DBMS_RANDOM.VALUE(30,50);

MySQL ではこう書き換えると同じことができる。

select round( rand() * 20 + 30 ) into var_standard_price;

実際にプロシージャを作成して実行してみるとこんな感じ。

5.6.10-log awsuser: [mydb] 09:32> delimiter //
5.6.10-log awsuser: [mydb] 09:32> create procedure rand_test()
    -> begin
    -> declare var_standard_price decimal (6, 2);
    -> select round( rand() * 20 + 30 ) into var_standard_price;
    -> select var_standard_price;
    -> end
    -> //
Query OK, 0 rows affected (0.02 sec)

5.6.10-log awsuser: [mydb] 09:32> delimiter ;
5.6.10-log awsuser: [mydb] 09:33> call rand_test();
+--------------------+
| var_standard_price |
+--------------------+
|              35.00 |
+--------------------+
1 row in set (0.02 sec)

Query OK, 0 rows affected (0.02 sec)

5.6.10-log awsuser: [mydb] 09:33> call rand_test();
+--------------------+
| var_standard_price |
+--------------------+
|              45.00 |
+--------------------+
1 row in set (0.01 sec)

Query OK, 0 rows affected (0.01 sec)

参考