Hatena::ブログ(Diary)

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

2018-03-17

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

設定


設定確認

% 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

クエリを確認する


参考

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 に記録されるクエリの長さを拡張する

設定変更

確認

  • 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


補足

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

2018-03-03

SHOW ENGINE INNODB STATUS の History list length

SHOW ENGINE INNODB STATUS の History list length の見方をメモ。

mysql> show engine innodb status\G

(中略)
------------
  TRANSACTIONS
------------
Trx id counter 0 80157601
Purge done for trx's n:o <0 80154573 undo n:o <0 0 
History list length 6
Total number of lock structs in row lock hash table 0

参考

High Performance MySQL: Optimization, Backups, and Replication

High Performance MySQL: Optimization, Backups, and Replication

  • Appendix B. MySQL Server Status
    • SHOW ENGINE INNODB STATUS
      • TRANSACTIONS

TRANSACTIONS

This section contains a little summary information about InnoDB transactions, followed by a list of the currently active transactions. Here are the first few lines (the header):

1  ------------
2  TRANSACTIONS
3  ------------
4  Trx id counter 0 80157601
5  Purge done for trx's n:o <0 80154573 undo n:o <0 0
6  History list length 6
7  Total number of lock structs in row lock hash table 0

The output varies depending on the MySQL version, but it includes at least the following:

  • Line 4: the current transaction identifier, which is a system variable that increments for each new transaction.
  • Line 5: the transaction ID to which InnoDB has purged old MVCC row versions. You can see how many old versions haven’t yet been purged by looking at the difference between this value and the current transaction ID. There’s no hard and fast rule as to how large this number can safely get. If nothing is updating any data, a large number doesn’t mean there’s unpurged data, because all the transactions are actually looking at the same version of the database. On the other hand, if many rows are being updated, one or more versions of each row is staying in memory. The best policy for reducing overhead is to ensure that transactions commit when they’re done instead of staying open a long time, because even an open transaction that doesn’t do any work keeps InnoDB from purging old row versions.Also in line 5: the undo log record number InnoDB’s purge process is currently working on, if any. If it’s “0 0”, as in our example, the purge process is idle.
  • Line 6: the history list length, which is the number of pages in the undo space in InnoDB’s data files. When a transaction performs updates and commits, this number increases; when the purge process removes the old versions, it decreases. The purge process also updates the value in line 5.
  • Line 7: the number of lock structs. Each lock struct usually holds many row locks, so this is not the same as the number of rows locked.

で、私がいつも見ているのはこれ。

mysql> SHOW ENGINE INNODB STATUS\G
..
------------
TRANSACTIONS
------------
Trx id counter 22588
Purge done for trx's n:o < 22588 undo n:o < 0 state: running but idle
History list length 678
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 2, OS thread handle 0x7f6bd0094700, query id 13 localhost root init
show engine innodb status
---TRANSACTION 22275, ACTIVE 1397 sec rollback
ROLLING BACK 542497 lock struct(s), heap size 64420280, 100542496 row lock(s), undo log entries 52636267
MySQL thread id 1, OS thread handle 0x7f6bd00d5700, query id 8 localhost root init
ROLLBACK
--------
FILE I/O
--------
..

これは今、手でROLLBACKを叩いてロールバックしているところですが、TRANSACTION 22275, ..の次の行に、undo log entriesの記載があります。

これが今、このトランザクション内の操作でUNDOセグメントに載っているレコードの数。UNDOセグメントからレコードを全部引っ張り出せばロールバックが終わるので、これが0に近付いていくのを見て、なんとなく進捗を知ります。

InnoDBのロールバックがあとどれくらいかかるかをなんとなく見積もる | GMOメディア エンジニアブログ
  • innodb_purge_threads
    • あまり意識している人はいない気がするパラメータ。5.6ではデフォルト1、5.7ではデフォルト4となっています。更新が多く、show engine innodb status\Gを見た場合に History list length [数字] の数字が肥大化していっている場合は増やす事が推奨されます。但しMySQL再起動が必要です。History list lengthが増えているということはundo領域(デフォルトではibdata1と同居)が肥大化する要因となるため気を配ったほうが良いです。またHistory list lengthが大きくなっていくと基本的には性能が劣化する傾向があります。
    • 何か時間の超絶かかるSELECTとかが実行されている場合もHistory list lengthが増える事があります。その場合は増やしてもたいした効果はないと考えられます(だってpurge出来ないし)
    • なお、過去の記憶ですが、無駄に増やしすぎるとコンテキストスイッチが増加して少ない設定の時よりも性能が下がるので程ほどに設定して下さい。5.7なら殆どのケースでデフォルトで十分だと思います。
MySQL関連のパラメータ(主にInnoDB)について - hiroi10の日記

  • The InnoDB Shared Tablespace (ibdata1) is Growing in Spite of Using innodb_file_per_table (Document ID 1472410.1)
  • How to Investigate InnoDB Lock Issues? (Documnet ID 1531774.1)

2018-02-25

Redshift のリザルトキャッシュを無効化する方法

性能試験などで敢えてリザルトキャッシュを使わずにクエリ性能を計測したい場合は以下の手順で無効化できる。


手順

set enable_result_cache_for_session=off;
  • ユーザーレベルで無効化する方法
ALTER USER awsuser SET enable_result_cache_for_session = off;

設定変更例

% psql "host=dc18xl4.*********.ap-northeast-1.redshift.amazonaws.com user=****** dbname=****** port=5439"
Password:
Timing is on.
psql (9.6.2, server 8.0.2)
SSL connection (protocol: TLSv1.2, cipher: ECDHE-RSA-AES256-GCM-SHA384, bits: 256, compression: on)
Type "help" for help.

# show enable_result_cache_for_session;
 enable_result_cache_for_session
---------------------------------
 on
(1 row)

# set enable_result_cache_for_session=off;
SET

# show enable_result_cache_for_session;
 enable_result_cache_for_session
---------------------------------
 off
(1 row)

参考

Amazon Redshift で結果をキャッシュして繰り返しクエリに一秒未満で応答

投稿日: Nov 21, 2017

Amazon Redshift で、結果をキャッシュしてクエリの再実行時にキャッシュ済みの結果を返すことで、繰り返しクエリのパフォーマンスを向上させました。

繰り返しクエリを実行するダッシュボード、可視化、およびビジネスインテリジェンス (BI) の各ツールでは、結果のキャッシュによりパフォーマンスが大幅に向上します。さらに、結果のキャッシュで解放されるリソースにより、他のすべてのクエリのパフォーマンスが向上します。

クエリを実行すると、Amazon Redshift はキャッシュを検索し、以前の実行でキャッシュされた結果がないか確認します。キャッシュ済みの結果が見つかり、データが変更されていないことがわかるとクエリを再実行せずに、キャッシュ済みの結果を即座に返します。キャッシュ済みの結果がないか、データが変更されている場合は、クエリを再実行して、今後の実行に備えて新しい結果をキャッシュします。キャッシュ済みの結果が返されると、処理リソースが節約されて他のクエリに振り向けられます。

今回のリリースでは、新しい ‘source_query’ 列を SVL_QLOG ビューに追加しています。クエリで結果のキャッシュを使用すると、この列が表示されます。結果のキャッシュは、デフォルトで、すべての Amazon Redshift クラスターで有効になっています。詳細については、関連ドキュメントを参照してください。

最新リリースでは、Amazon Redshift の結果のキャッシュをすべての AWS パブリックリージョンで使用できます。

Amazon Redshift で結果をキャッシュして繰り返しクエリに一秒未満で応答

enable_result_cache_for_session

値 (デフォルトは太字)

on (true)、off (false)

説明

クエリ結果のキャッシュを使用するかどうかを指定します。enable_result_cache_for_session が on の場合、Amazon Redshift は、クエリ結果の有効なキャッシュ済みコピーを、クエリ送信された際に確認します。結果のキャッシュに一致が見つかった場合、Amazon Redshift はキャッシュ済みの結果を使用しクエリを実行しません。enable_result_cache_for_session が off の場合、Amazon Redshift は結果のキャッシュを無視し、送信されたクエリをすべて実行します。

enable_result_cache_for_session - Amazon Redshift

Announcement: Amazon Redshift Maintenance (November 16th – December 14th, 2017)

We will be patching your Amazon Redshift clusters during your system maintenance window in the coming weeks. The timing of the patch will depend on your region and maintenance window settings. You can view or change your maintenance window settings from the AWS Management Console. After your cluster has been patched, the new cluster version will be Build 1.0.1535. Please contact us at redshift-feedback@amazon.com if you have any questions.

This version includes the following new features and improvements:

Result-set caching. Repetitive queries can now be served directly from the memory of the leader node of your Amazon Redshift cluster, significantly enhancing query performance

https://forums.aws.amazon.com/thread.jspa?threadID=132076&start=75&tstart=0

SVL_QLOG ビューにはデータベースに対して実行されたすべてのクエリのログが含まれます。

(中略)

source_query: integer: クエリで結果のキャッシュが使用された場合、キャッシュされた結果のソースとなったクエリクエリ ID。結果のキャッシュが使用されていない場合、このフィールドの値は NULL です。

https://docs.aws.amazon.com/ja_jp/redshift/latest/dg/r_SVL_QLOG.html

2018-01-21

PostgreSQL で "Too many open files in system" が発生する

事象

以下のエラーがログに出力される。

Too many open files in system

考察

Linux のカーネルパラメータ fs.file-max はシステム全体でオープンできるファイルディスクリプタ数、つまり PostgreSQL 以外がオープンするファイルディスクリプタも含まれる。

PostgreSQL がオープンするファイルディスクリプタ数は max_files_per_process でサーバ子プロセスごとにオープンできる上限を設定できる。ソケットを使うときもファイルディスクリプタをオープンするので max_connections の数もファイルのディスクリプタ数に関係する。


参考

max_files_per_process (integer)

それぞれのサーバ子プロセスが同時にオープンできるファイル数の最大値をセットします。 デフォルトは1000ファイルです。 もしもカーネルがプロセス毎の安全制限を強要している場合、この設定を気にかける必要はありません。 しかし、いくつかのプラットフォーム(特にほとんどのBSDシステム)では、もし多くのプロセス全てがそれだけ多くのファイルを開くことを試みたとした場合、実際にサポートできるファイル数より多くのファイルを開くことを許しています。もしも「Too many open files」エラーが発生した場合、この設定を削減してみてください。 このパラメータサーバ起動時にのみ設定可能です。

19.4. 資源の消費

3.2.1. カーネルパラメータ

Linux カーネルのパラメータ設定により、PostgreSQL が使用するシステムのリソースの制限を変更することができます。システム全体でオープン可能なファイル数や接続数に応じたセマフォの全体数、共有メモリサイズなど、規模に応じたシステムリソース容量の設定を行います。カーネルパラメータの設定値については、マニュアル9を参考にしてください。

カーネルパラメータ説明関連する PostgreSQLパラメータ
fs.file-maxシステム全体で使用可能なファイルディスクリプタ数を指定する。PostgreSQL のバックエンドプロセスが同時にオープンするファイル数の設定と最大接続数から、PostgreSQL が要求するファイルディスクリプタ数を確認することができる。max_files_per_process
バックエンドプロセスが要求する最大ファイルディスクリプタ数。
max_connections
DB への最大接続数。
https://www.pgecons.org/wp-content/uploads/PGECons/2013/WG2/11_PerformanceTuning.pdf