LoginSignup
0
0

Db2で一定時間以上かかった長時間SQLをログに記録する

Posted at

目的

  • Db2上で処理時間の長いSQLを後から確認したい
  • 全てのSQLを記録する必要はなく、長いものだけ把握したい

方法

他にも方法は数多ありそうですが、今回は

  1. DB2 ワークロード・マネージャー (WLM) で長時間SQLを検出
  2. 検出されたSQLのステートメントおよびコンパイル環境のデータをアクティビティ・イベントモニターへ送信

の二段階で、詳細情報をログファイルに残せるかどうか確認します。
 → イベントモニターの出力先ファイルに出力されたので、目的は達成できました

設定手順

以下、WLM/イベントモニターの構成コマンドをスクリプト化した内容をそのまま添付しています。Db2インスタンスオーナーにて db2 -tvf <ファイル名> で実行すると、構成できます。

1. Db2 WLM構成

以下のワークロードと閾値の定義を作成します

  • 対象アプリ:コマンド行からのSQL実行時(db2bp)
  • 詳細情報の収集:アクティビティイベントモニターへの送信
  • 閾値:1分
  • 閾値を超えた場合のアクション:実行停止
  • 対象ユーザ:PUBLIC(全員)
-- コマンド行プロセッサ(db2bp)からのアクセス時に有効となるワークロードを定義
CREATE WORKLOAD work1_wl
APPLNAME('db2bp')
POSITION AT 1
;
-- 閾値を定義(1分以上かかるSQLがあったらアクティビティデータを収集の上、実行停止)
CREATE THRESHOLD th_totalacttime
FOR WORKLOAD work1_wl ACTIVITIES
ENFORCEMENT DATABASE
WHEN ACTIVITYTOTALTIME > 1 MINUTES
COLLECT ACTIVITY DATA WITH DETAILS, SECTION AND VALUES
STOP EXECUTION
;
-- ワークロードの利用権限を付与
GRANT USAGE ON WORKLOAD work1_wl TO PUBLIC
;

2. Db2 アクティビティイベントモニター構成

以下のアクティビティイベントモニターを作成します

  • 出力先:ファイル (指定したディレクトリ配下にファイルが作成される)
-- 詳細なアクティビティー情報を記録するためのアクティビティー・イベント・モニターを作成
CREATE EVENT MONITOR ACTIVITIES FOR ACTIVITIES WRITE TO FILE '/database/uktmp/act/logs'
;

-- 作成したイベント・モニターを使用可能にする
SET EVENT MONITOR ACTIVITIES STATE 1
;

長時間SQLの実行とログ出力確認

1. 長時間SQL実行

実際に長時間かかるSQLを流してみます

$ db2 connect to testdb
--- 中略 ---
$ date ; time db2 "select CAST(sum(1) as BIGINT) from t1 a, t1 b, t1 c, t1 d, t1 e, t1 f,  t1 g, t1 h, t1 i, t1 j, t1 k, t1 l, t1 m, t1 n, t1 o, t1 p, t1 q, t1 r, t1 s, t1 t, t1 u, t1 v, t1 w, t1 x, t1 y, t1 z" ; date
Wed Dec 27 07:48:40 UTC 2023

1
--------------------
SQL4712N  The activity or request was stopped because the threshold
"TH_TOTALACTTIME" has been exceeded. Reason code: "9".  SQLSTATE=5U026

real    1m0.906s
user    0m0.000s
sys     0m0.018s
Wed Dec 27 07:49:41 UTC 2023

→ 1分を超えた時点で想定通り中断されました

2. ログ出力確認

イベントモニター作成時に指定したパスに、ファイル 00000000.evt が生成されていることを確認します

$ ls -ltr
total 140
-rw-r----- 1 db2inst1 db2iadm1     36 Dec 27 07:40 db2event.ctl
-rw-r--r-- 1 db2inst1 db2iadm1 115552 Dec 27 07:49 00000000.evt

→ ファイルが生成されておりタイムスタンプもSQL実行時刻近辺で更新されています

3. イベントモニター出力のフォーマット

バイナリフォーマットで出力されるため、フォーマットします
出力量が多いため、適当なファイルにリダイレクトしておきます

$ db2evmon -path '/database/uktmp/act/logs' > actmon.text.log

4. フォーマット後のログ確認

想定通り、1分をえて実行されたSQLについてのみ、出力されています
以下のような情報が収集されます

  • イベント発生時のタイムスタンプ
  • アプリケーション名(db2bp)
  • 接続ユーザ名(DB2CL1)
  • 接続元アドレス
  • 閾値に抵触したSQL(ステートメント)
  • 閾値に抵触したSQLの見積もりコスト
  • 閾値に抵触したSQLの実行時間(言うても1分)
  • 閾値に抵触したSQLのPrepare所要時間
  • 閾値に抵触したSQLの種別(動的 / 静的)
  • 閾値に抵触したSQLの分離レベル
  • 統計ファブリケーション所要時間
  • 同期Runstats所要時間
  • ソートやHash Join, Hash Group by などの実行状況
  • ロックタイムアウト値
フォーマット済のイベントモニター出力(ファイル)
--------------------------------------------------------------------------
                            EVENT LOG HEADER
  Event Monitor name: ACTIVITIES
  Server Product ID: SQL11058
  Version of event monitor data: 12
  Byte order: LITTLE ENDIAN
  Number of nodes in db2 instance: 1
  Codepage of database: 1208
  Territory code of database: 1
  Server instance name: db2inst1
--------------------------------------------------------------------------

--------------------------------------------------------------------------
  Database Name: TESTDB  
  Database Path: /database/data/db2inst1/NODE0000/SQL00001/MEMBER0000/
  First connection timestamp: 12/27/2023 07:23:07.863062
  Event Monitor Start time:   12/27/2023 07:40:50.239539
--------------------------------------------------------------------------

3) Activity ...
  Activity ID                        : 1
  Activity Secondary ID              : 0
  Appl Handle                        : 1666
  UOW ID                             : 14
  Service Superclass Name            : SYSDEFAULTUSERCLASS
  Service Subclass Name              : SYSDEFAULTMANAGEDSUBCLASS
  Tenant ID                          : 0
  Tenant Name                        : SYSTEM

  Activity Type                      : READ_DML
  Parent Activity ID                 : 0
  Parent UOW ID                      : 0
  Coordinating Partition             : 0
  Workload ID                        : 3
  Workload Occurrence ID             : 2
  Database Work Action Set ID        : 0
  Database Work Class ID             : 0
  Service Class Work Action Set ID   : 2147483647
  Service Class Work Class ID        : 2147483647
  Workload Work Action Set ID        : 0
  Workload Work Class ID             : 0
  Time Created                       : 12/27/2023 07:48:40.475596
  Time Started                       : 12/27/2023 07:48:40.475606
  Time Completed                     : 12/27/2023 07:49:41.359494
  Event Timestamp                    : 12/27/2023 07:49:41.359582
  Time Created at Coordinator Member : 12/27/2023 07:48:40.475596
  Activity captured while in progress: FALSE

  Application ID                     : 127.0.0.1.35180.231227072307
  Application Name                   : db2bp
  Session Auth ID                    : DB2CL1  
  Client Userid                      : 
  Client Workstation Name            : 
  Client Applname                    :  
  Client Accounting String           : 
  Address                            : 127.0.0.1
  SQLCA:
   sqlcode: -4712
   sqlstate: 5U026

  Message: SQL4712N  The activity or request was stopped because the threshold "TH_TOTALACTTIME" has been exceeded. Reason code: "9".  SQLSTATE=5U026


  Query Cost Estimate     : 9223372036854775807
  Query Card Estimate     : 1
  Execution time          : 60.883888 seconds
  Rows Returned           : 0
  Query Actual Degree     : 1
  Effective Query Degree  : 1

  Prep time: 2

  Number of remaps: 0

  Total stats fabrication time: 0

  Total stats fabrications: 0

  Total sync runstats time: 0

  Total sync runstats: 0
  Monitoring Interval ID  : 0
  Query Data Tag List     : 
  Active Hash Group Bys Top               : 0
  Active Hash Joins Top                   : 0
  Active OLAP Functions Top               : 0
  Active Partial Early Aggregations Top   : 0
  Active Partial Early Distincts Top      : 0
  Active Sort Consumers Top               : 0
  Active Sorts Top                        : 0
  Active Columnar Vector Consumers Top    : 0
  Sort Consumer Heap Top                  : 0
  Sort Consumer Shared Heap Top           : 0
  Sort Heap Top                           : 0
  Sort Shared Heap Top                    : 0
  Admission Control Bypassed              : FALSE
  Estimated Sort Shared Heap Top          : 0
  Estimated Sort Consumers Top            : 0
  Estimated Runtime                       : 9223372036854775807
  Admission Resource Actuals              : N
  Agents Top                              : 0
  Session Priority                        : MEDIUM
  Details XML             : <activity_metrics xmlns="http://www.ibm.com/xmlns/prod/db2/mon" release="11050800"><wlm_queue_time_total>0</wlm_queue_time_total><wlm_queue_assignments_total>0</wlm_queue_assignments_total><fcm_tq_recv_wait_time>0</fcm_tq_recv_wait_time><fcm_message_recv_wait_time>0</fcm_message_recv_wait_time><fcm_tq_send_wait_time>0</fcm_tq_send_wait_time><fcm_message_send_wait_time>0</fcm_message_send_wait_time><lock_wait_time>0</lock_wait_time><lock_waits>0</lock_waits><direct_read_time>0</direct_read_time><direct_read_reqs>0</direct_read_reqs><direct_write_time>0</direct_write_time><direct_write_reqs>0</direct_write_reqs><log_buffer_wait_time>0</log_buffer_wait_time><num_log_buffer_full>0</num_log_buffer_full><log_disk_wait_time>0</log_disk_wait_time><log_disk_waits_total>0</log_disk_waits_total><pool_write_time>0</pool_write_time><pool_read_time>0</pool_read_time><audit_file_write_wait_time>0</audit_file_write_wait_time><audit_file_writes_total>0</audit_file_writes_total><audit_subsystem_wait_time>0</audit_subsystem_wait_time><audit_subsystem_waits_total>0</audit_subsystem_waits_total><diaglog_write_wait_time>0</diaglog_write_wait_time><diaglog_writes_total>0</diaglog_writes_total><fcm_send_wait_time>0</fcm_send_wait_time><fcm_recv_wait_time>0</fcm_recv_wait_time><total_act_wait_time>0</total_act_wait_time><total_section_sort_proc_time>0</total_section_sort_proc_time><total_section_sort_time>0</total_section_sort_time><total_section_sorts>0</total_section_sorts><total_act_time>60884</total_act_time><rows_read>1454672895</rows_read><rows_modified>288247596</rows_modified><pool_data_l_reads>98</pool_data_l_reads><pool_index_l_reads>0</pool_index_l_reads><pool_temp_data_l_reads>4341242</pool_temp_data_l_reads><pool_temp_index_l_reads>0</pool_temp_index_l_reads><pool_xda_l_reads>0</pool_xda_l_reads><pool_temp_xda_l_reads>0</pool_temp_xda_l_reads><total_cpu_time>60858298</total_cpu_time><pool_data_p_reads>0</pool_data_p_reads><pool_temp_data_p_reads>0</pool_temp_data_p_reads><pool_xda_p_reads>0</pool_xda_p_reads><pool_temp_xda_p_reads>0</pool_temp_xda_p_reads><pool_index_p_reads>0</pool_index_p_reads><pool_temp_index_p_reads>0</pool_temp_index_p_reads><pool_data_writes>0</pool_data_writes><pool_xda_writes>0</pool_xda_writes><pool_index_writes>0</pool_index_writes><direct_reads>0</direct_reads><direct_writes>0</direct_writes><rows_returned>0</rows_returned><deadlocks>0</deadlocks><lock_timeouts>0</lock_timeouts><lock_escals>0</lock_escals><fcm_sends_total>0</fcm_sends_total><fcm_recvs_total>0</fcm_recvs_total><fcm_send_volume>0</fcm_send_volume><fcm_recv_volume>0</fcm_recv_volume><fcm_message_sends_total>0</fcm_message_sends_total><fcm_message_recvs_total>0</fcm_message_recvs_total><fcm_message_send_volume>0</fcm_message_send_volume><fcm_message_recv_volume>0</fcm_message_recv_volume><fcm_tq_sends_total>0</fcm_tq_sends_total><fcm_tq_recvs_total>0</fcm_tq_recvs_total><fcm_tq_send_volume>0</fcm_tq_send_volume><fcm_tq_recv_volume>0</fcm_tq_recv_volume><tq_tot_send_spills>0</tq_tot_send_spills><post_threshold_sorts>0</post_threshold_sorts><post_shrthreshold_sorts>0</post_shrthreshold_sorts><sort_overflows>0</sort_overflows><audit_events_total>0</audit_events_total><total_sorts>0</total_sorts><stmt_exec_time>60884</stmt_exec_time><coord_stmt_exec_time>60884</coord_stmt_exec_time><total_routine_non_sect_proc_time>0</total_routine_non_sect_proc_time><total_routine_non_sect_time>0</total_routine_non_sect_time><total_section_proc_time>60884</total_section_proc_time><total_section_time>60884</total_section_time><total_app_section_executions>1</total_app_section_executions><total_routine_user_code_proc_time>0</total_routine_user_code_proc_time><total_routine_user_code_time>0</total_routine_user_code_time><total_routine_time>0</total_routine_time><thresh_violations>1</thresh_violations><num_lw_thresh_exceeded>0</num_lw_thresh_exceeded><total_routine_invocations>0</total_routine_invocations><lock_wait_time_global>0</lock_wait_time_global><lock_waits_global>0</lock_waits_global><reclaim_wait_time>0</reclaim_wait_time><spacemappage_reclaim_wait_time>0</spacemappage_reclaim_wait_time><lock_timeouts_global>0</lock_timeouts_global><lock_escals_maxlocks>0</lock_escals_maxlocks><lock_escals_locklist>0</lock_escals_locklist><lock_escals_global>0</lock_escals_global><cf_wait_time>0</cf_wait_time><cf_waits>0</cf_waits><pool_data_gbp_l_reads>0</pool_data_gbp_l_reads><pool_data_gbp_p_reads>0</pool_data_gbp_p_reads><pool_data_lbp_pages_found>4341340</pool_data_lbp_pages_found><pool_data_gbp_invalid_pages>0</pool_data_gbp_invalid_pages><pool_index_gbp_l_reads>0</pool_index_gbp_l_reads><pool_index_gbp_p_reads>0</pool_index_gbp_p_reads><pool_index_lbp_pages_found>0</pool_index_lbp_pages_found><pool_index_gbp_invalid_pages>0</pool_index_gbp_invalid_pages><pool_xda_gbp_l_reads>0</pool_xda_gbp_l_reads><pool_xda_gbp_p_reads>0</pool_xda_gbp_p_reads><pool_xda_lbp_pages_found>0</pool_xda_lbp_pages_found><pool_xda_gbp_invalid_pages>0</pool_xda_gbp_invalid_pages><evmon_wait_time>0</evmon_wait_time><evmon_waits_total>0</evmon_waits_total><total_extended_latch_wait_time>0</total_extended_latch_wait_time><total_extended_latch_waits>1</total_extended_latch_waits><total_disp_run_queue_time>0</total_disp_run_queue_time><pool_queued_async_data_reqs>0</pool_queued_async_data_reqs><pool_queued_async_index_reqs>0</pool_queued_async_index_reqs><pool_queued_async_xda_reqs>0</pool_queued_async_xda_reqs><pool_queued_async_temp_data_reqs>90663</pool_queued_async_temp_data_reqs><pool_queued_async_temp_index_reqs>0</pool_queued_async_temp_index_reqs><pool_queued_async_temp_xda_reqs>0</pool_queued_async_temp_xda_reqs><pool_queued_async_other_reqs>12</pool_queued_async_other_reqs><pool_queued_async_data_pages>0</pool_queued_async_data_pages><pool_queued_async_index_pages>0</pool_queued_async_index_pages><pool_queued_async_xda_pages>0</pool_queued_async_xda_pages><pool_queued_async_temp_data_pages>2901350</pool_queued_async_temp_data_pages><pool_queued_async_temp_index_pages>0</pool_queued_async_temp_index_pages><pool_queued_async_temp_xda_pages>0</pool_queued_async_temp_xda_pages><pool_failed_async_data_reqs>0</pool_failed_async_data_reqs><pool_failed_async_index_reqs>0</pool_failed_async_index_reqs><pool_failed_async_xda_reqs>0</pool_failed_async_xda_reqs><pool_failed_async_temp_data_reqs>0</pool_failed_async_temp_data_reqs><pool_failed_async_temp_index_reqs>0</pool_failed_async_temp_index_reqs><pool_failed_async_temp_xda_reqs>0</pool_failed_async_temp_xda_reqs><pool_failed_async_other_reqs>0</pool_failed_async_other_reqs><total_peds>0</total_peds><disabled_peds>0</disabled_peds><post_threshold_peds>0</post_threshold_peds><total_peas>0</total_peas><post_threshold_peas>0</post_threshold_peas><tq_sort_heap_requests>0</tq_sort_heap_requests><tq_sort_heap_rejections>0</tq_sort_heap_rejections><prefetch_wait_time>0</prefetch_wait_time><prefetch_waits>0</prefetch_waits><pool_data_gbp_indep_pages_found_in_lbp>4341340</pool_data_gbp_indep_pages_found_in_lbp><pool_index_gbp_indep_pages_found_in_lbp>0</pool_index_gbp_indep_pages_found_in_lbp><pool_xda_gbp_indep_pages_found_in_lbp>0</pool_xda_gbp_indep_pages_found_in_lbp><fcm_tq_recv_waits_total>0</fcm_tq_recv_waits_total><fcm_message_recv_waits_total>0</fcm_message_recv_waits_total><fcm_tq_send_waits_total>0</fcm_tq_send_waits_total><fcm_message_send_waits_total>0</fcm_message_send_waits_total><fcm_send_waits_total>0</fcm_send_waits_total><fcm_recv_waits_total>0</fcm_recv_waits_total><ida_send_wait_time>0</ida_send_wait_time><ida_sends_total>0</ida_sends_total><ida_send_volume>0</ida_send_volume><ida_recv_wait_time>0</ida_recv_wait_time><ida_recvs_total>0</ida_recvs_total><ida_recv_volume>0</ida_recv_volume><rows_deleted>0</rows_deleted><rows_inserted>0</rows_inserted><rows_updated>0</rows_updated><total_hash_joins>0</total_hash_joins><total_hash_loops>0</total_hash_loops><hash_join_overflows>0</hash_join_overflows><hash_join_small_overflows>0</hash_join_small_overflows><post_shrthreshold_hash_joins>0</post_shrthreshold_hash_joins><total_olap_funcs>0</total_olap_funcs><olap_func_overflows>0</olap_func_overflows><int_rows_deleted>0</int_rows_deleted><int_rows_inserted>0</int_rows_inserted><int_rows_updated>0</int_rows_updated><comm_exit_wait_time>0</comm_exit_wait_time><comm_exit_waits>0</comm_exit_waits><pool_col_l_reads>0</pool_col_l_reads><pool_temp_col_l_reads>0</pool_temp_col_l_reads><pool_col_p_reads>0</pool_col_p_reads><pool_temp_col_p_reads>0</pool_temp_col_p_reads><pool_col_lbp_pages_found>0</pool_col_lbp_pages_found><pool_col_writes>0</pool_col_writes><pool_col_gbp_l_reads>0</pool_col_gbp_l_reads><pool_col_gbp_p_reads>0</pool_col_gbp_p_reads><pool_col_gbp_invalid_pages>0</pool_col_gbp_invalid_pages><pool_col_gbp_indep_pages_found_in_lbp>0</pool_col_gbp_indep_pages_found_in_lbp><pool_queued_async_col_reqs>0</pool_queued_async_col_reqs><pool_queued_async_temp_col_reqs>0</pool_queued_async_temp_col_reqs><pool_queued_async_col_pages>0</pool_queued_async_col_pages><pool_queued_async_temp_col_pages>0</pool_queued_async_temp_col_pages><pool_failed_async_col_reqs>0</pool_failed_async_col_reqs><pool_failed_async_temp_col_reqs>0</pool_failed_async_temp_col_reqs><total_col_proc_time>0</total_col_proc_time><total_col_time>0</total_col_time><total_col_executions>0</total_col_executions><post_threshold_hash_joins>0</post_threshold_hash_joins><pool_caching_tier_page_read_time>0</pool_caching_tier_page_read_time><pool_caching_tier_page_write_time>0</pool_caching_tier_page_write_time><pool_data_caching_tier_l_reads>0</pool_data_caching_tier_l_reads><pool_index_caching_tier_l_reads>0</pool_index_caching_tier_l_reads><pool_xda_caching_tier_l_reads>0</pool_xda_caching_tier_l_reads><pool_col_caching_tier_l_reads>0</pool_col_caching_tier_l_reads><pool_data_caching_tier_page_writes>0</pool_data_caching_tier_page_writes><pool_index_caching_tier_page_writes>0</pool_index_caching_tier_page_writes><pool_xda_caching_tier_page_writes>0</pool_xda_caching_tier_page_writes><pool_col_caching_tier_page_writes>0</pool_col_caching_tier_page_writes><pool_data_caching_tier_page_updates>0</pool_data_caching_tier_page_updates><pool_index_caching_tier_page_updates>0</pool_index_caching_tier_page_updates><pool_xda_caching_tier_page_updates>0</pool_xda_caching_tier_page_updates><pool_col_caching_tier_page_updates>0</pool_col_caching_tier_page_updates><pool_data_caching_tier_pages_found>0</pool_data_caching_tier_pages_found><pool_index_caching_tier_pages_found>0</pool_index_caching_tier_pages_found><pool_xda_caching_tier_pages_found>0</pool_xda_caching_tier_pages_found><pool_col_caching_tier_pages_found>0</pool_col_caching_tier_pages_found><pool_data_caching_tier_gbp_invalid_pages>0</pool_data_caching_tier_gbp_invalid_pages><pool_index_caching_tier_gbp_invalid_pages>0</pool_index_caching_tier_gbp_invalid_pages><pool_xda_caching_tier_gbp_invalid_pages>0</pool_xda_caching_tier_gbp_invalid_pages><pool_col_caching_tier_gbp_invalid_pages>0</pool_col_caching_tier_gbp_invalid_pages><pool_data_caching_tier_gbp_indep_pages_found>0</pool_data_caching_tier_gbp_indep_pages_found><pool_index_caching_tier_gbp_indep_pages_found>0</pool_index_caching_tier_gbp_indep_pages_found><pool_xda_caching_tier_gbp_indep_pages_found>0</pool_xda_caching_tier_gbp_indep_pages_found><pool_col_caching_tier_gbp_indep_pages_found>0</pool_col_caching_tier_gbp_indep_pages_found><total_hash_grpbys>0</total_hash_grpbys><hash_grpby_overflows>0</hash_grpby_overflows><post_threshold_hash_grpbys>0</post_threshold_hash_grpbys><post_threshold_olap_funcs>0</post_threshold_olap_funcs><post_threshold_col_vector_consumers>0</post_threshold_col_vector_consumers><total_col_vector_consumers>0</total_col_vector_consumers><total_index_build_proc_time>0</total_index_build_proc_time><total_index_build_time>0</total_index_build_time><total_indexes_built>0</total_indexes_built><ext_table_recv_wait_time>0</ext_table_recv_wait_time><ext_table_recvs_total>0</ext_table_recvs_total><ext_table_recv_volume>0</ext_table_recv_volume><ext_table_read_volume>0</ext_table_read_volume><ext_table_send_wait_time>0</ext_table_send_wait_time><ext_table_sends_total>0</ext_table_sends_total><ext_table_send_volume>0</ext_table_send_volume><ext_table_write_volume>0</ext_table_write_volume><col_vector_consumer_overflows>0</col_vector_consumer_overflows><total_col_synopsis_proc_time>0</total_col_synopsis_proc_time><total_col_synopsis_time>0</total_col_synopsis_time><total_col_synopsis_executions>0</total_col_synopsis_executions><col_synopsis_rows_inserted>0</col_synopsis_rows_inserted><lob_prefetch_wait_time>0</lob_prefetch_wait_time><lob_prefetch_reqs>0</lob_prefetch_reqs><fed_rows_deleted>0</fed_rows_deleted><fed_rows_inserted>0</fed_rows_inserted><fed_rows_updated>0</fed_rows_updated><fed_rows_read>0</fed_rows_read><fed_wait_time>0</fed_wait_time><fed_waits_total>0</fed_waits_total><adm_overflows>0</adm_overflows><adm_bypass_act_total>0</adm_bypass_act_total></activity_metrics>

4) Activity Statement ...
  Activity ID             : 1
  Activity Secondary ID   : 0
  Application Handle      : 1666
  Application ID          : 127.0.0.1.35180.231227072307
  UOW ID                  : 14

  Lock timeout value      : -1
  Query ID                : 0
  Package cache ID        : 4050154160129
  Statement ID            : 5746028695146687320
  Plan ID                 : -7165985729113726549
  Semantic Env ID         : 4836717360601346174
  Package creator         : NULLID  
  Package name            : SQLC2P31
  Package version         : 
  Section No              : 201
  Statement No            : 1
  Num Routines            : 0
  Executable ID           : 0x01000000000000003B0000000000000000000000020020231227074840475395
  Type                    : Dynamic
  Nesting level of stmt   : 0
  Source ID               : 0
  Invocation ID           : 0
  Routine ID              : 0
  Isolation level         : Cursor Stability
  Statement text          : select CAST(sum(1) as BIGINT) from t1 a, t1 b, t1 c, t1 d, t1 e, t1 f,  t1 g, t1 h, t1 i, t1 j, t1 k, t1 l, t1 m, t1 n, t1 o, t1 p, t1 q, t1 r, t1 s, t1 t, t1 u, t1 v, t1 w, t1 x, t1 y, t1 z
  Effective statement text : 

  Stmt first use time     : 12/27/2023 07:48:40.475596
  Stmt last use time      : 12/27/2023 07:48:40.475596
  Event Timestamp                    : 12/27/2023 07:49:41.359582
  Time Created at Coordinator Member : 12/27/2023 07:48:40.475596

SQL実行履歴取得、これ以外のユースケース

今回試した以外にも、様々なユースケース/情報収集ツールがあります。
要件に沿っていろいろな構成方法・情報収集・抽出の方法が取れそうです。

遅いSQLのパラメーターマーカー値を特定したい場合

状況に応じた、様々なSQL処理時間・処理内容追跡方法

  • Db2:遅いSQLを見つける方法
    • ロックによる遅延の把握,DBを流れるSQLの概況把握,全SQLの捕捉‥などさまざまな要件に応じた追跡方法とメリデメが紹介されていて勉強になります

実行されたすべてのSQLを履歴として記録に残したい場合

参考情報

補足

調べたことメモ。

アクティビティ・イベント・モニターとは?

Db2のマニュアルによれば以下のような機能だそうです。

  • ステートメントのパフォーマンスと動作、ならびにシステム全般のロードのパフォーマンスと動作をより深く理解するために役立つデータを収集
  • 以下の表関数が戻すデータを補完するデータを戻す
    • MON_GET_ACTIVITY_DETAILS
    • MON_GET_PKG_CACHE_STMT
    • MON_GET_PKG_CACHE_STMT_DETAILS
  • 他のイベント・モニターと一緒に使用すると特に有用
    • 例えば、定義したしきい値に違反するステートメントの実行に関する情報をキャプチャーする(※今回はこの用途で利用)
  • 収集されたデータの書き込み先はDb2の表/名前付きパイプ/ファイル を選択可能

しきい値違反イベントモニターとの併用?

類似の手順がマニュアルの「例: ステートメントの実行に関連したアクティビティー情報のキャプチャー」に取り上げられています。
このキャプチャー例では、イベントモニターを2つ仕掛けています。

  • しきい値違反イベントモニター
  • アクティビティーイベントモニター

しきい値違反イベントモニターは、しきい値違反を記録するためのモニターで、これもあわせて設定してみると、しきい値違反の発生についても別途、記録が取れるようになります。
アクティビティーイベントモニターの出力内容自体には差異がありませんでしたので、今回の目的であれば、必須ではないと感じました。
(逆に、しかけた閾値に何回抵触したかをカウントしたいだけの目的ならば、このイベントモニターをしかけておくだけでいいのかもしれません。ファイルサイズも小さく収まる)

--------------------------------------------------------------------------
                            EVENT LOG HEADER
  Event Monitor name: STMT_THRESH_VIOLATIONS
  Server Product ID: SQL11057
  Version of event monitor data: 12
  Byte order: LITTLE ENDIAN
  Number of nodes in db2 instance: 1
  Codepage of database: 1208
  Territory code of database: 1
  Server instance name: db2inst1
--------------------------------------------------------------------------

--------------------------------------------------------------------------
  Database Name: TESTDB  
  Database Path: /database/data/db2inst1/NODE0000/SQL00001/MEMBER0000/
  First connection timestamp: 12/28/2023 01:28:24.891704
  Event Monitor Start time:   12/28/2023 01:36:14.167410
--------------------------------------------------------------------------

3) Threshold Violation ...
  Threshold ID                 : 1
  Activity ID                  : 1
  Appl Handle                  : 63
  Application ID               : *LOCAL.db2inst1.231228014225
  Application Name             : db2bp
  UOW ID                       : 2
  Workload ID                  : 3
  Coordinating Partition       : 0
  Partition Number             : 0
  Tenant Name                  : SYSTEM
  Tenant Id                    : 0
  Connection Start Time        : 12/28/2023 01:42:25.005277
  Time of Violation            : 12/28/2023 01:44:19.000000
  Threshold Max Value          : 60
  Threshold Queue Size         : 0
  Activity Collected?          : Yes
  Threshold Predicate          : ActivityTotalTime
  Threshold Action             : Stop
  Source Service Class ID      : 0
  Destination Service Class ID : 0
  Client User ID               : 
  Client Workstation Name      : 
  Client Application Name      : 
  Client Account String        : 
  Session Authorization  ID    : DB2CL1  
  System Authorization  ID     : DB2CL1  
  Client PID                   : 21766
  Client Product ID            : SQL11057
  Client Hostname              : 23460cf8ce40
  Client Platform              : LINUXX8664
  Client Communication Protocol: LOCAL
  Client Port Number           : 0
0
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
0
0