Monitor zdarzeń (db2 event monitor)

Monitor zdarzeń pozwala na zbieranie informacji dotyczących wybranego zdarzenia.Typowym przykłądem jest pojawianie się zakleszczeń. Uchwycenie momentu kiedy się pojawiają jest bardzo trudne. W tejd sytuacji można posłużyć się właśnie monitorem zdarzeń który automatycznie zbierze informacje o zakleszczeniu gdy tylko się on pojawi. Można go również wykorzystać do zbierania informacji na temat statycznych i dynamicznych instrukcji SQL.

Na początku podłączamy się do bazy danych DB2:

[db2inst1@localhost evmon]$ db2 connect to SAMPLE

  Database Connection Information

 Database server        = DB2/LINUXX8664 9.7.6
 SQL authorization ID   = DB2INST1
 Local database alias   = SAMPLE 

Tworzymy też oddzielny folder gdzie będziemy umieszczać pliki EVT z zapisanymi danymi (binarnymi)

[db2inst1@localhost ~]$ mkdir evmon
[db2inst1@localhost ~]$ cd evmon/
[db2inst1@localhost evmon]$ pwd

/db2/db2home/db2inst1/evmon 

Następnie tworzymy monitor zdarzeń (w naszym przypadku nazwiemy go EVMONITOR:

db2 => create event monitor EVMONITOR FOR DATABASE, STATEMENTS WRITE to file '/db2/db2home/db2inst1/evmon'

DB20000I  The SQL command completed successfully. 

W powyższym poleceniu możemy zdefiniować jakie obszary chcemy monitorować:
DATABASE - bazę danych
STATEMENTS - instrukcje
DEADLOCKS - zakleszczenia
TABLESPACES - przestrzenie tabel
BUFFERPOOLS - pule buforów
CONENCTIONS - połaczenia
TRANSACTIONS - transakcje

Uruchamiamy monitor zdarzeń

db2 => set event monitor EVMONITOR STATE=1

DB20000I  The SQL command completed successfully. 

teraz wykonujemy operacje na bazach, które są zapisywane do pliku logu monitora zdarzeń. Po zakonczeniu pracy wyłączamy monitor zdarzeń.

db2 => set event monitor EVMONITOR STATE=0

DB20000I  The SQL command completed successfully. 

Jesli nie będziemy potrzebowali monitora zdarzeń możemy go usunąć:

db2 => drop event monitor EVMONITOR

DB20000I  The SQL command completed successfully. 

Przechodzimy do folderu z logami monitora zdarzeń. Utworzyły się tam pliki z logami o wielkości około 4MB

[db2inst1@localhost evmon]$ ls -la

total 29488
drwxr-xr-x   2 db2inst1 db2iadm1    4096 Sep 21 09:30 .
drwxr-xr-x. 14 db2inst1 db2iadm1    4096 Sep 21 09:08 ..
-rw-r--r--   1 db2inst1 db2iadm1 4082247 Sep 21 09:11 00000000.evt
-rw-r--r--   1 db2inst1 db2iadm1 4092408 Sep 21 09:14 00000001.evt
-rw-r--r--   1 db2inst1 db2iadm1 4095863 Sep 21 09:18 00000002.evt
-rw-r--r--   1 db2inst1 db2iadm1 4082810 Sep 21 09:20 00000003.evt
-rw-r--r--   1 db2inst1 db2iadm1 4091836 Sep 21 09:24 00000004.evt
-rw-r--r--   1 db2inst1 db2iadm1 4092325 Sep 21 09:28 00000005.evt
-rw-r--r--   1 db2inst1 db2iadm1 4082187 Sep 21 09:30 00000006.evt
-rw-r--r--   1 db2inst1 db2iadm1 1550186 Sep 21 09:32 00000007.evt
-rw-r-----   1 db2inst1 db2iadm1      35 Sep 21 09:30 db2event.ctl 

Plik logu jest binarny więc go nie podejrzymy zwykłymi narzędziami typu more lub less. Do przeglądania pliku służy narzędzie DB2EVMON. Opcja more pozwoli na stopniowe odczytanie logu.

db2evmon -path '/db2/db2home/db2inst1/evmon' | more

Można go przerobić tym narzędziem na plik testowy

[db2inst1@localhost evmon]$ db2evmon -path '/db2/db2home/db2inst1/evmon' > log.txt

Reading /db2/db2home/db2inst1/evmon/00000000.evt ... 

Przykładowy log:



--------------------------------------------------------------------------
                            EVENT LOG HEADER
  Event Monitor name: EVMONITOR
  Server Product ID: SQL09076
  Version of event monitor data: 11
  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: SAMPLE  
  Database Path: /db2/db2home/db2inst1/db2inst1/NODE0000/SQL00001/
  First connection timestamp: 09/20/2017 21:44:44.438081
  Event Monitor Start time:   09/20/2017 21:59:51.904306
--------------------------------------------------------------------------

3) Connection Header Event ...
  Appl Handle: 7
  Appl Id: *LOCAL.db2inst1.170920194444
  Appl Seq number: 00014
  DRDA AS Correlation Token: *LOCAL.db2inst1.170920194444
  Program Name    : db2bp
  Authorization Id: DB2INST1
  Execution Id    : db2inst1
  Codepage Id: 1208
  Territory code: 1
  Client Process Id: 2442
  Client Database Alias: SAMPLE
  Client Product Id: SQL09076
  Client Platform: Linux/X8664
  Client Communication Protocol: Local
  Client Network Name: localhost.localdomai
  Connect timestamp: 09/20/2017 21:44:44.438081

6) Statement Event ...
  Appl Handle: 34
  Appl Id: *LOCAL.db2inst1.170920195545
  Appl Seq number: 00004

  Record is the result of a flush: FALSE
  -------------------------------------------
  Type     : Dynamic
  Operation: Prepare
  Section  : 201
  Creator  : NULLID  
  Package  : SQLC2H23
  Consistency Token  : AAAAABBc
  Package Version ID  : 
  Cursor   : SQLCUR201
  Cursor was blocking: FALSE
  Text     : select * from DB2INST1.EMPLOYEE
  -------------------------------------------
  Start Time: 09/20/2017 22:00:07.446390
  Stop Time:  09/20/2017 22:00:07.535148
  Elapsed Execution Time:  0.088758 seconds
  Number of Agents created: 1
  User CPU: 0.005910 seconds
  System CPU: 0.000000 seconds
  Statistic fabrication time (milliseconds): 0
  Synchronous runstats time  (milliseconds): 0
  Fetch Count: 42
  Sorts: 0
  Total sort time: 0
  Sort overflows: 0
  Rows read: 42
  Rows written: 0
  Internal rows deleted: 0
  Internal rows updated: 0
  Internal rows inserted: 0
  Bufferpool data logical reads: 1
  Bufferpool data physical reads: 0
  Bufferpool temporary data logical reads: 0
  Bufferpool temporary data physical reads: 0
  Bufferpool index logical reads: 0
  Bufferpool index physical reads: 0
  Bufferpool temporary index logical reads: 0
  Bufferpool temporary index physical reads: 0
  Bufferpool xda logical page reads: 0
  Bufferpool xda physical page reads: 0
  Bufferpool temporary xda logical page reads: 0
  Bufferpool temporary xda physical page reads: 0
  SQLCA:
   sqlcode: 0
   sqlstate: 00000

11) Transaction Event ... --- to zdarzenie dotyczy poprzedniego Statement Event
  Appl Handle: 34
   
  Record is the result of a flush: FALSE
  Appl Id: *LOCAL.db2inst1.170920195545
  Appl Seq number: 00004   
  Completion Status: Committed
  Start time: 09/20/2017 22:00:07.446390
  Stop time:  09/20/2017 22:00:07.542513
  Elapsed Execution Time:  0.096123 seconds
  Previous transaction stop time: Not Available
  User CPU: 0.006938 seconds
  System CPU: 0.000000 seconds
  Lock wait time: 0
  Maximum number of locks held: 13
  Lock escalations: 0
  X lock escalations: 0
  Rows Read: 43
  Rows Written: 0
  Log space used: 0

25) Database Event

 Record is the result of a flush: FALSE

 Lock Statistics:
  Lock Waits: 0
  Total time waited on locks (milliseconds): 0
  Deadlocks: 0
  Lock escalations:  0
  X lock escalations:  0
  Lock timeouts:  0

 Sort Statistics:
  Sorts: 2
  Total sort time (milliseconds): 0
  Sort overflows: 0
  Sort share heap high water mark: 256
  Post Shared Memory Threshold Sorts: 0

 Hash Statistics:
  Hash Joins: 0
  Hash Loops: 0
  Hash Join Small Overflows: 0
  Hash Join Overflows: 0
  Post Shared Memory Threshold Hash Joins: 0

 OLAP Statistics:
  OLAP Functions: 0
  OLAP Function Overflows: 0

 Buffer Pool Statistics:
  Buffer pool data logical page reads: 45
  Buffer pool data physical page reads: 3
  Buffer pool temporary data logical page reads: 0
  Buffer pool temporary data physical page reads: 0
  Buffer pool data page writes: 0
  Buffer pool index logical page reads: 51
  Buffer pool index physical page reads: 10
  Buffer pool temporary index logical page reads: 0
  Buffer pool temporary index physical page reads: 0
  Buffer pool index page writes: 0
  Buffer pool xda logical page reads: 14
  Buffer pool xda physical page reads: 3
  Buffer pool temporary xda logical page reads: 0
  Buffer pool temporary xda physical page reads: 0
  Buffer pool xda page writes: 0
  Buffer pool read time (milliseconds): 47
  Buffer pool write time (milliseconds): 0
  Files closed: 0
  Buffer pool asynch data page reads: 0
  Buffer pool asynch data page read reqs: 0
  Buffer pool asynch data writes: 0
  Buffer pool asynch index page reads: 0
  Buffer pool asynch index page read reqs: 0
  Buffer pool asynch index page writes: 0
  Buffer pool asynch xda page reads: 0
  Buffer pool asynch xda page read reqs: 0
  Buffer pool asynch xda writes: 0
  Buffer pool asynch read time: 0
  Buffer pool asynch write time: 0
  No victim buffers available: 0
  Buffer pool LSN gap cleans: 0
  Buffer pool dirty page steal cleans: 0
  Buffer pool dirty page threshold cleans: 0
  Time spent waiting for a prefetch: 0 milliseconds
  Unread prefetch pages: 0

 Direct I/O Statistics:
  Sectors read directly: 82
  Sectors written directly: 0
  Direct read requests: 9
  Direct write requests: 0
  Direct read time: 208
  Direct write time: 0

 SQL Statement counts
  Commit SQL statements: 4
  Rollback SQL statements: 0
  Dynamic SQL statements: 19
  Static SQL stmts: 4
  Failed SQL statements: 0
  Select SQL statements: 3
  Xquery statements: 0
  Data Definition Language SQL statements: 0
  Update/Insert/Delete SQL statements: 0

 Internal counts
  Internal auto rebinds: 0
  Internal rows deleted: 0
  Internal rows updated: 0
  Internal rows inserted: 0
  Internal commits: 1
  Internal rollbacks: 0

 Row counts
  Rows deleted: 0
  Rows inserted: 0
  Rows updated: 0
  Rows selected: 93
  Rows read: 4173

 Binds/Precompiles: 0

 Connection Statistics
  Connections since 1st connect: 0
  Maximum number of connections: 10

 Heap Statistics
  Maximum amount of database heap used: 19791872

 Logging Statistics
  Maximum Secondary Log space used: 0
  Maximum Total Log space used: 1127410
  Log space required for recovery: 0
  Log held up by dirty pages: 0
  Log pages read: 0
  Log read time: 0.000000000 seconds
  Log pages written: 0
  Log write time: 0.000000000 seconds
  Number IO log reads:  0
  Number IO log writes:  0
  Number partial IO:  0
  Log buffer full:  0
  Log data in buffer:  0
  MDC blocks pending cleanup:  0
  File number of first active log:  0
  File number of last active log:  2
  File number of current log:  0
  File number of log being archived:  4294967295

 Package Cache Statistics
  Package Cache Lookups: 6
  Package Cache Inserts: 3
  Package Cache number of overflows: 0
  Package Cache high water mark: 1312392

 Application Section Retrieval Statistics
  Application Section Lookups: 19
  Application Section Inserts: 3

 Catalog Cache Statistics
  Catalog Cache Lookups: 21
  Catalog Cache Inserts: 2
  Catalog Cache Overflows: 0
  Catalog cache high water mark: 356288
  Catalog cache statistics size: 10032

 Statistics collection activities
  Statistic fabrications: 1
  Synchronous runstats: 0
  Asynchronous runstats: 0
  Total statistic fabrication time (milliseconds): 2
  Total synchronous runstats time (milliseconds): 0

 Memory usage:

  Node Number: 0
   Memory Pool Type:  Backup/Restore/Util Heap
     Current size (bytes): 65536
     High water mark (bytes): 2949120
     Configured size (bytes): 20512768

  Node Number: 0
   Memory Pool Type:  Package Cache
     Current size (bytes): 1441792
     High water mark (bytes): 1441792
     Configured size (bytes): 1310720

  Node Number: 0
   Memory Pool Type:  Other Memory
     Current size (bytes): 262144
     High water mark (bytes): 262144
     Configured size (bytes): 20971520

  Node Number: 0
   Memory Pool Type:  Catalog Cache Heap
     Current size (bytes): 458752
     High water mark (bytes): 458752
     Configured size (bytes): 851968

 Last Disconnection Time: 09/20/2017 22:00:38.779920

Wszystkie zdarzenie w logu są kolejno ponumerowane. Niestety zdarzenia różnych zakresów są wymieszane w jednym logu (czasami wielkości kilku GB). Aby je rozdzielić i ułatwić ich odczyt najlepiej je umieścić w tabelach bazy danych.

ZAPIS ZDARZEŃ Z EVENT MONITORA DO TABEL BAZY DANYCH

Aby był porządek w tabelach i nie mieszać tabel Event Monitora z tabelami użytkownika proponuję utworzyć specjalny przestrzeń tabel (tablespace) dedykowaną na takie właśnie tabele. Nie będzie on nam zapychał naszego tablespace i łatwiej będzie go można usunąć.

db2 => CREATE TABLESPACE EVENTMON
DB20000I The SQL command completed successfully.

db2 => LIST TABLESPACES

          Tablespaces for Current Database

 ...

 Tablespace ID                        = 7
 Name                                 = EVENTMON
 Type                                 = Database managed space
 Contents                             = All permanent data. Large table space.
 State                                = 0x0000
   Detailed explanation:
     Normal

Tworzymy Event Monitora z zakresu STATEMENTS z zapisem do tabeli db2inst1.MYEVENT

db2 => create event monitor EVMON_STATEMENT FOR STATEMENTS WRITE TO TABLE STMT(TABLE db2inst1.MYEVENT IN EVENTMON)

Sprawdzamy czy tabela powstała:

db2 => select substr(TABSCHEMA,1,15) AS SCHEMA,substr(TABNAME,1,15) AS TABLE,TBSPACEID,substr(TBSPACE,1,15) AS TABLESPACE from syscat.tables where TBSPACE='EVENTMON'

SCHEMA          TABLE           TBSPACEID TABLESPACE
--------------- --------------- --------- ---------------
DB2INST1        MYEVENT                 7 EVENTMON

  1 record(s) selected.

Uruchamiamy działanie monitora zdarzeń EVMON_STATEMENT

db2 => set event monitor EVMON_STATEMENT STATE=1

Teraz wykonujemy różne działania na bazie (selecty, inserty itd). Po ich zakończeniu wyłączamy monitor zdarzeń:

db2 => set event monitor EVMON_STATEMENT STATE=0

Jeśli już nie będziemy go używać, możemy go usunąć:

db2 => drop event monitor EVMON_STATEMENT

Możemy teraz spraqdzić co nam się zarejestrowało

select substr(APPL_ID,1,30) as APPL_ID,START_TIME,' ',STOP_TIME,(timestampdiff(2, char(timestamp(STOP_TIME) - char(timestamp(START_TIME))))) as time, ROWS_READ as ROW_READ,ROWS_WRITTEN as ROW_WRITTEN,TOTAL_SORTS as TOTAL_SORTS, USER_CPU_TIME as USER_CPU_TIME, substr(STMT_TEXT,1,100) as STMT_TEXT from MYEVENT

APPL_ID                        START_TIME                 3 STOP_TIME                  TIME        ROW_READ             ROW_WRITTEN          TOTAL_SORTS          USER_CPU_TIME        STMT_TEXT                                                                                          
------------------------------ -------------------------- - -------------------------- ----------- -------------------- -------------------- -------------------- -------------------- ----------------------------------------------------------------------------------------------------
*LOCAL.db2inst1.170922141843   2017-09-22-16.32.51.177101   2017-09-22-16.32.51.177225           0                    0                    0                    0                  120                                                                                                    
*LOCAL.db2inst1.170922141843   2017-09-22-16.32.51.177242   2017-09-22-16.32.51.183938           0                    4                    0                    0                 3518 SELECT TABNAME, TABSCHEMA, TYPE, CREATE_TIME FROM SYSCAT.TABLES WHERE TABSCHEMA = USER ORDER BY TABS
*LOCAL.db2inst1.170922141843   2017-09-22-16.32.51.184045   2017-09-22-16.32.51.184064           0                    0                    0                    0                   16 SELECT TABNAME, TABSCHEMA, TYPE, CREATE_TIME FROM SYSCAT.TABLES WHERE TABSCHEMA = USER ORDER BY TABS
...
*LOCAL.db2inst1.170922143342   2017-09-22-16.33.37.925242   2017-09-22-16.33.37.925252           0                    0                    0                    0                    7                                                                                                    
*LOCAL.db2inst1.170922143342   2017-09-22-16.33.37.934739   2017-09-22-16.33.37.935380           0                    0                    0                    0                   90                                                                                                    
*LOCAL.db2inst1.170922143342   2017-09-22-16.33.37.935703   2017-09-22-16.33.37.935717           0                    0                    0                    0                   10                                                                                                    
*LOCAL.db2inst1.170922143342   2017-09-22-16.33.37.935854   2017-09-22-16.33.37.935869           0                    0                    0                    0                   10                                                                                                    

  61 record(s) selected.

W podanym zapytaniu dodałem kolumnę w której jest obliczany czas wykonania zapytanie.
Funkcja timestampdiff oblicza różnicę pomiędzy END_TIME i START_TIME. Pierwszy parametr (w zapytaniu równy 2) określa w jakich jednostkach ma być podana różnica czasów:

1 Fractions of a second (przykładowo 179997800)
2 Seconds (179s)
4 Minutes (2min)
8 Hours (0h)
16 Days (0d)
32 Weeks
64 Months
128 Quarters
256 Years

Po wykorzystaniu zarejestrowanych danych z monitora zdarzeń możemy usunąć tabele i całą przestrzeń tabel:

db2 => DROP TABLE db2inst1.MYEVENT

db2 => DROP TABLESPACE EVENTMON

DB20000I  The SQL command completed successfully.

Jesli nie interesuje nas gdzie lądują dane (w kórej tabeli) możemy skorzystać z domyślnych tabel DB2 EVENT MONITOR'a.
Podczas tworzenia monitora zdarzeń nie podajemy wtedy nazwy tabeli :

create event monitor EVMON_STATEMENT FOR STATEMENTS WRITE TO TABLE
create event monitor EVMON_CONNECTIONS FOR CONNECTIONS WRITE TO TABLE
create event monitor EVMON_DATABASES FOR DATABASES WRITE TO TABLE
create event monitor EVMON_ACTIVITY FOR ACTIVITIES WRITE TO TABLE
create event monitor EVMON_DEADLOCK FOR DEADLOCKS WITH DETAILS WRITE TO TABLE

Powstają odpowiednio dla każdego zakresu zdarzeń tabele:

CONNHEADER_EVMON_CONNECT
CONNMEMUSE_EVMON_CONNECT
CONN_EVMON_CONNECT
CONTROL_EVMON_CONNECT

STMT_EVMON_STATEMENT
CONNHEADER_EVMON_STATEMENT
CONTROL_EVMON_STATEMENT

CONNHEADER_EVMON_CONNECT
CONNMEMUSE_EVMON_CONNECT
CONN_EVMON_CONNECT
CONTROL_EVMON_CONNECT

CONTROL_EVMON_DATABAS
DBMEMUSE_EVMON_DATABAS
DB_EVMON_DATABAS

ACTIVITYMETRICS_EVMON_ACTIVITY
ACTIVITYSTMT_EVMON_ACTIVITY
ACTIVITYVALS_EVMON_ACTIVITY
ACTIVITY_EVMON_ACTIVITY
CONTROL_EVMON_ACTIVITY

CONNHEADER_EVMON_DEADLOCK
CONTROL_EVMON_DEADLOCK
DEADLOCK_EVMON_DEADLOCK
DLCONN_EVMON_DEADLOCK
DLLOCK_EVMON_DEADLOCK

itd

Nazwy kolumn poszczególnych tabel możemy sprawdzić oczywiście poleceniem:

DESCRIBE TABLE nazwa_tabeli

Ten wpis został opublikowany w kategorii DB2. Dodaj zakładkę do bezpośredniego odnośnika.

Dodaj komentarz