[ after @ 03.01.2016. 16:07 ] @
Srecna Nova 2016 svima!

Jedna od veoma finih stvari u mysql (od verzije 5.0) je mysqldumpslow alatka koja cita mysql slow log i sumarizuje upite.
Od upita:

Code:

select * from table where col1='ABCD' and col2='XXX' and col3=15;
select * from table where col1='C' and col2='y' and col3=1;
select * from table where col1='nesto' and col2='Z' and col3=100;


sumarizuje (isti tip) upite u:

Code:

select * from table where col1='S' and col2='S' and col3=N;


sa statistikom: #count, avg time, examined rows, sent rows etc

Percona(Maatkit) ima naprednjiju alatku pt-query-digest, koja daje siru sliku. Npr. isti tip upita je izvrsen 5x; prva 4x izvrsenje je trajalo par ms a zadnje izvrsenje 100s iz nekog razloga - pik koji se vise nikad nije javio... mysqldumpslow bi taj upit prikazao kao upit sa avg execution time ~ 20s, dok bi perkonin pt-query-digest prikazao kao 95% izvrsenja od par ms i jedan pik od 100s...

U svakom slucaju mysqldumpslow daje lep pregled problematicnih upita kao i onih na koje ne bi trebalo uopste obracati paznju. Na osnovu sortiranja po time i count npr. dolazimo do upita koji je problematican: avg time 2s; count 4000 (2x4000=8000s), dok upit cije je izvrsenje 50s mozemo ignorisati jer ima count 4 (50x4=200s)... Za bolje parsiranje i vise opcija i startnih info tu je perkonin tool.

Medjutim u MySQL 5.7 mysqldumpslow jednostavno ne radi i ne parsira kako treba - avg time, rows sent/examined itd uvek je 0.00s ili sumarizuje u N. Sumarizuje i ono sto ne treba npr. host IP prikazuje uvek sumarizovano kao N.N.N.N. Tako da jedan efektan i jednostavan za koriscenje alat od verzije 5.0 u najnovijoj 5.7 verziji je skoro pa neupotrebljiv. Jedino sto mi pada na pamet da posto je promenjen datetime format loga (slow/general/error) u 5.7. to zaglupi mysqldumpslow i ne moze da parsira kako treba iako ne prijavi nikakvu gresku.


[att_img] http://s17.postimg.org/xb29tjxjz/slow_log.jpg



[att_img] http://s11.postimg.org/vi29hzm1f/mysqldumpslow.jpg


Isti upiti/baza i iste opcije sa mysqldumpslow rade bas kako treba u 5.5.


Format datetime loga u 5.7:

Code:

2015-12-16T11:55:19.262207Z 0 [Note] InnoDB: Buffer pool(s) load completed at 151216 12:55:19



Format datetime loga u nizim verzijama (5.5)


Code:

2013-05-08 13:48:14 8546 [Note] InnoDB: Completed initialization of buffer pool



Probao sam sa menjanjem variable log_timestamps = UTC | SYSTEM ali rezultat je isti sto se tice mysqldumpslow prikaza.

Nisam nasao na netu da neko ima slican problem u 5.7. Mozda niko i ne koristi vise mysqldumpslow :). Inace pt-query-digest radi sasvim ok u 5.7.
[ bogdan.kecman @ 03.01.2016. 20:17 ] @
Code:

[[email protected]]$ cat SPORI57.log
/home/arhimed/MYSQL/5.7.7/bin/mysqld, Version: 5.7.7-rc-log (MySQL Community Server (GPL)). started with:
Tcp port: 5707  Unix socket: /tmp/mysql_sandbox5707.sock
Time                 Id Command    Argument
# Time: 2016-01-03T19:49:16.917840Z
[email protected]: msandbox[msandbox] @ localhost []  Id:     2
# Query_time: 10.000174  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1287;
select sleep(10);

[[email protected]]$ cat SPORI55.log
/home/arhimed/MYSQL/5.5.43/bin/mysqld, Version: 5.5.43-log (MySQL Community Server (GPL)). started with:
Tcp port: 5543  Unix socket: /tmp/mysql_sandbox5543.sock
Time                 Id Command    Argument
# Time: 160103 20:47:23
[email protected]: msandbox[msandbox] @ localhost []
# Query_time: 10.000160  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1451850443;
select sleep( 10);




Code:

msb_5_7_7]$ ./my sqldumpslow  data/SPORI57.log

Reading mysql slow query log from data/SPORI57.log
Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), [email protected]
  # Time: N-N-03T19:N:N.917840Z
  # [email protected]: msandbox[msandbox] @ localhost []  Id:     N
  # Query_time: N.N  Lock_time: N.N Rows_sent: N  Rows_examined: N
  SET timestamp=N;
  select sleep(N)


msb_5_5_43]$ ./my sqldumpslow  data/SPORI55.log

Reading mysql slow query log from data/SPORI55.log
Count: 1  Time=10.00s (10s)  Lock=0.00s (0s)  Rows=1.0 (1), msandbox[msandbox]@localhost
  select sleep( N)



prijavi bug na bugs.mysql.com javi mi broj, ja cu ga assigneujem i verifikujem .. def je bug unutar mysqlbugslow

a bug je zato sto realno niko od nas to vise ne koristi .. vec smo se svi uveliko bacili na SYS tabelu (koja je od skoro default u 5.7) mozes da je dodas na starije mysql-ove odavde https://github.com/mysql/mysql-sys

a dobijes super fore, na primer:

Code:

mysql [localhost] {msandbox} (sys) > call ps_statement_avg_latency_histogram()\G
*************************** 1. row ***************************
Performance Schema Statement Digest Average Latency Histogram:

  . = 1 unit
  * = 2 units
  # = 3 units

(0 - 625ms)       17 | .................
(625 - 1250ms)    0  |
(1250 - 1875ms)   0  |
(1875 - 2500ms)   0  |
(2500 - 3125ms)   0  |
(3125 - 3750ms)   0  |
(3750 - 4375ms)   0  |
(4375 - 5000ms)   1  | .
(5000 - 5625ms)   0  |
(5625 - 6250ms)   0  |
(6250 - 6875ms)   0  |
(6875 - 7500ms)   0  |
(7500 - 8125ms)   0  |
(8125 - 8750ms)   0  |
(8750 - 9375ms)   0  |
(9375 - 10000ms)  0  |

  Total Statements: 19; Buckets: 16; Bucket Size: 625 ms;

1 row in set (0.01 sec)

Query OK, 0 rows affected (0.01 sec)

mysql [localhost] {msandbox} (sys) >


Code:

mysql [localhost] {msandbox} (sys) > select * from statements_with_runtimes_in_95th_percentile\G
*************************** 1. row ***************************
            query: SELECT `sleep` (?)
               db: NULL
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 10.00 s
      max_latency: 10.00 s
      avg_latency: 10.00 s
        rows_sent: 1
    rows_sent_avg: 1
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 20:49:17
        last_seen: 2016-01-03 20:49:17
           digest: ae08b499b311f3019f48705c57308bc5
*************************** 2. row ***************************
            query: SELECT `sleep` (?)
               db: sys
        full_scan:
       exec_count: 4
        err_count: 0
       warn_count: 0
    total_latency: 19.00 s
      max_latency: 10.00 s
      avg_latency: 4.75 s
        rows_sent: 4
    rows_sent_avg: 1
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:06:55
        last_seen: 2016-01-03 21:07:09
           digest: ae08b499b311f3019f48705c57308bc5
*************************** 3. row ***************************
            query: DROP TRIGGER IF EXISTS `sys_config_insert_set_user`
               db: sys
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 124.86 ms
      max_latency: 124.86 ms
      avg_latency: 124.86 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:37
        last_seen: 2016-01-03 21:11:37
           digest: ddaff94202129815e12fad3bd15da7e4
*************************** 4. row ***************************
            query: CREATE DEFINER = ? @? TRIGGER  ... YSTEM_USER ( ) ; END IF ; END
               db: sys
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 84.04 ms
      max_latency: 84.04 ms
      avg_latency: 84.04 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:37
        last_seen: 2016-01-03 21:11:37
           digest: a8a61c19ced64afc05408704249a0642
*************************** 5. row ***************************
            query: CREATE OR REPLACE ALGORITHM =  ... _USER , `sum_timer_wait` DESC
               db: sys
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 83.79 ms
      max_latency: 83.79 ms
      avg_latency: 83.79 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:40
        last_seen: 2016-01-03 21:11:40
           digest: 2642beaa8693fddfad08b2d1221e7180
*************************** 6. row ***************************
            query: CREATE DEFINER = ? @? TRIGGER  ... YSTEM_USER ( ) ; END IF ; END
               db: sys
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 83.68 ms
      max_latency: 83.68 ms
      avg_latency: 83.68 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:37
        last_seen: 2016-01-03 21:11:37
           digest: 0801b750a0d870b86b43d14126f84b95
*************************** 7. row ***************************
            query: SELECT IF ( `isnull` ( `perfor ... _host_by_event_name` GROUP BY
               db: sys
        full_scan:
       exec_count: 2
        err_count: 0
       warn_count: 0
    total_latency: 150.53 ms
      max_latency: 108.53 ms
      avg_latency: 75.27 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:40
        last_seen: 2016-01-03 21:11:41
           digest: d49f26677aab427cb8ea00056198e1e6
*************************** 8. row ***************************
            query: CREATE OR REPLACE ALGORITHM =  ... _USER , `sum_timer_wait` DESC
               db: sys
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 74.83 ms
      max_latency: 74.83 ms
      avg_latency: 74.83 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:41
        last_seen: 2016-01-03 21:11:41
           digest: 8ba6433238f4826e1dda4d85e63d20b3
*************************** 9. row ***************************
            query: CREATE OR REPLACE ALGORITHM =  ... _USER , `sum_timer_wait` DESC
               db: sys
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 58.76 ms
      max_latency: 58.76 ms
      avg_latency: 58.76 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:40
        last_seen: 2016-01-03 21:11:40
           digest: e8752d8cc47d43a2f81f733e8c3c8586
*************************** 10. row ***************************
            query: CREATE OR REPLACE ALGORITHM =  ... _by_digest` GROUP BY `avg_us`
               db: sys
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 58.76 ms
      max_latency: 58.76 ms
      avg_latency: 58.76 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:39
        last_seen: 2016-01-03 21:11:39
           digest: d901984c0e8fafad54a3b65be30f317b
*************************** 11. row ***************************
            query: CREATE OR REPLACE ALGORITHM =  ... _USER , `sum_timer_wait` DESC
               db: sys
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 58.47 ms
      max_latency: 58.47 ms
      avg_latency: 58.47 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:41
        last_seen: 2016-01-03 21:11:41
           digest: 19bb5362461539d587eb5fd7099ec0b8
11 rows in set (0.05 sec)

mysql [localhost] {msandbox} (sys) >


Code:


mysql [localhost] {msandbox} (sys) >  CALL sys.statement_performance_analyzer('overall', NULL, 'with_runtimes_in_95th_percentile')\G
*************************** 1. row ***************************
summary: Disabled 1 thread
1 row in set (0.00 sec)

*************************** 1. row ***************************
Next Output: Queries with Runtime in 95th Percentile
1 row in set (0.01 sec)

*************************** 1. row ***************************
            query: SELECT `sleep` (?)
               db: NULL
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 10.00 s
      max_latency: 10.00 s
      avg_latency: 10.00 s
        rows_sent: 1
    rows_sent_avg: 1
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 20:49:17
        last_seen: 2016-01-03 20:49:17
           digest: ae08b499b311f3019f48705c57308bc5
*************************** 2. row ***************************
            query: SELECT `sleep` (?)
               db: sys
        full_scan:
       exec_count: 4
        err_count: 0
       warn_count: 0
    total_latency: 19.00 s
      max_latency: 10.00 s
      avg_latency: 4.75 s
        rows_sent: 4
    rows_sent_avg: 1
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:06:55
        last_seen: 2016-01-03 21:07:09
           digest: ae08b499b311f3019f48705c57308bc5
*************************** 3. row ***************************
            query: DROP TRIGGER IF EXISTS `sys_config_insert_set_user`
               db: sys
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 124.86 ms
      max_latency: 124.86 ms
      avg_latency: 124.86 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:37
        last_seen: 2016-01-03 21:11:37
           digest: ddaff94202129815e12fad3bd15da7e4
*************************** 4. row ***************************
            query: NULL
               db: sys
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 124.01 ms
      max_latency: 124.01 ms
      avg_latency: 124.01 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:15:03
        last_seen: 2016-01-03 21:15:03
           digest: NULL
*************************** 5. row ***************************
            query: CREATE DEFINER = ? @? TRIGGER  ... YSTEM_USER ( ) ; END IF ; END
               db: sys
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 84.04 ms
      max_latency: 84.04 ms
      avg_latency: 84.04 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:37
        last_seen: 2016-01-03 21:11:37
           digest: a8a61c19ced64afc05408704249a0642
*************************** 6. row ***************************
            query: CREATE OR REPLACE ALGORITHM =  ... _USER , `sum_timer_wait` DESC
               db: sys
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 83.79 ms
      max_latency: 83.79 ms
      avg_latency: 83.79 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:40
        last_seen: 2016-01-03 21:11:40
           digest: 2642beaa8693fddfad08b2d1221e7180
*************************** 7. row ***************************
            query: CREATE DEFINER = ? @? TRIGGER  ... YSTEM_USER ( ) ; END IF ; END
               db: sys
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 83.68 ms
      max_latency: 83.68 ms
      avg_latency: 83.68 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:37
        last_seen: 2016-01-03 21:11:37
           digest: 0801b750a0d870b86b43d14126f84b95
*************************** 8. row ***************************
            query: SELECT IF ( `isnull` ( `perfor ... _host_by_event_name` GROUP BY
               db: sys
        full_scan:
       exec_count: 2
        err_count: 0
       warn_count: 0
    total_latency: 150.53 ms
      max_latency: 108.53 ms
      avg_latency: 75.27 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:40
        last_seen: 2016-01-03 21:11:41
           digest: d49f26677aab427cb8ea00056198e1e6
*************************** 9. row ***************************
            query: CREATE OR REPLACE ALGORITHM =  ... _USER , `sum_timer_wait` DESC
               db: sys
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 74.83 ms
      max_latency: 74.83 ms
      avg_latency: 74.83 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:41
        last_seen: 2016-01-03 21:11:41
           digest: 8ba6433238f4826e1dda4d85e63d20b3
*************************** 10. row ***************************
            query: CREATE OR REPLACE ALGORITHM =  ... _USER , `sum_timer_wait` DESC
               db: sys
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 58.76 ms
      max_latency: 58.76 ms
      avg_latency: 58.76 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:40
        last_seen: 2016-01-03 21:11:40
           digest: e8752d8cc47d43a2f81f733e8c3c8586
*************************** 11. row ***************************
            query: CREATE OR REPLACE ALGORITHM =  ... _by_digest` GROUP BY `avg_us`
               db: sys
        full_scan:
       exec_count: 1
        err_count: 0
       warn_count: 0
    total_latency: 58.76 ms
      max_latency: 58.76 ms
      avg_latency: 58.76 ms
        rows_sent: 0
    rows_sent_avg: 0
    rows_examined: 0
rows_examined_avg: 0
       first_seen: 2016-01-03 21:11:39
        last_seen: 2016-01-03 21:11:39
           digest: d901984c0e8fafad54a3b65be30f317b
11 rows in set (0.13 sec)

*************************** 1. row ***************************
summary: Enabled 1 thread
1 row in set (0.14 sec)

Query OK, 0 rows affected (0.14 sec)

mysql [localhost] {msandbox} (sys) >


i tako dalje i tako dalje ...

dakle slowquerylog .. nije bas nesto od velike koristi u 5.7+
[ after @ 03.01.2016. 23:31 ] @
Hvala za info u vezi SYS tabele Bogdane!

Inace mysqldumpslow bug je reportiran (poslao sam ti detalje).

Pozz.
[ bogdan.kecman @ 03.01.2016. 23:55 ] @
nema na cemu, SYS je mnogo dobra stvar, nadam se da ce i drugi da
probaju .. tek na 5.7 "stvarno ubija kako radi"

za bug, verifikovan, prebacen u oracle sistem .. ja necu ga opravljam
mrzi me to ce indijci da preuzmu sada :D
[ Shadowed @ 04.01.2016. 00:01 ] @
Citat:
bogdan.kecman: to ce indijci da preuzmu sada :D

Razlog vise da se koristi sys tabela :D
[ nkrgovic @ 04.01.2016. 10:19 ] @
E, sys je zapravo odlican i za kapiranje kako radi MySQL. Cela sys schema ima jednu pomocnu tabelu, sve su view-ovi na information schema i performance schema. Kako krenes da je koristis, svhatis da su sve informacije vec sve vreme tu.... Ja sam cak prestao i sa onim jednostavnim komandama tipa "show processlist", pa presao na select iz information_schema tabele za sve :).
[ bogdan.kecman @ 04.01.2016. 10:22 ] @
i_s je i nastala da bi zamenila sve te "mysql specific" komande tipa
show processlist :D fora je da iz i_s mozes da izvuces sve te podatke
koje si radio sa show ovo ono :D
a p_s je tu za sve vezano za performanse :)