Upgrade to Pro — share decks privately, control downloads, hide ads and more …

Troubleshooting MySQL from a MySQL Developer Pe...

Troubleshooting MySQL from a MySQL Developer Perspective

Working as a MySQL Developer as part of the Bugs committee exposes you to a variety of bugs, such as server crashes, memory leaks, wrong query results, internal thread deadlocks, and others. In this talk, I will cover some of the technics we utilize to troubleshoot MySQL when things are not working as expected.

Some of the topics covered include:
Reproducible test cases
Git Bisect
Stack Traces
GDB
Record and Replay
By the end of this session, attendees will grasp how to tackle analyses of when software is not working as expected.

Marcelo Altmann

June 09, 2023
Tweet

More Decks by Marcelo Altmann

Other Decks in Programming

Transcript

  1. Marcelo Altmann • Software Developer @ Percona ◦ Joined in

    2016 as Senior Support Engineer ◦ PXB / PS / PXC ◦ Member Bugs Escalation Committee
  2. Software bug A software bug is an error, flaw or

    fault in computer software that causes it to produce an incorrect or unexpected result, or to behave in unintended ways - wikipedia • Wrong query results • Performance degradations • Security flaw • Crash
  3. Reproducible test case • Being able to reproduce a bug

    is key • Projects have their own test framework • Used to ensure we don't introduce regressions • MySQL MTR ◦ Start mysql instance: ./mtr --start alias & mysql –defaults-file=var/my.cnf ◦ Interactive GDB session: ./mtr --manual-gdb alias gdb -cd ./ -x ./var/tmp/gdbinit.mysqld.1 ../bin/mysqld
  4. Reproducible test case • Recompile with Debug synchronization : open_tables(...)

    DEBUG_SYNC(thd, "after_open_tables"); lock_tables(...) --connection conn1 SET DEBUG_SYNC= 'after_open_tables SIGNAL opened WAIT_FOR flushed'; send INSERT INTO t1 VALUES(1); --connection conn2 SET DEBUG_SYNC= 'now WAIT_FOR opened'; SET DEBUG_SYNC= 'after_abort_locks SIGNAL flushed'; FLUSH TABLE t1;
  5. Reproducible test case • Recompile with Test Faults Macros :

    somefile.cc DBUG_EXECUTE_IF("some_keyword", { some_function(); some_variable++; };); mysql> SET debug = '+d,some_keyword';
  6. Stack traces - signals • A way of software /

    kernel / user to communicate with a process. • Program will interpret and handle it - mysqld.cc my_init_signals()
  7. Stack traces - signals • SIGABRT / 6 - Code

    Assertions ◦ ut_a(condition) / ut_ad(condition) ◦ Critical points of code - continuing might cause damage • SIGSEGV / 11 - Segmentation Fault ◦ Memory access violation ◦ Tried to access restricted memory area • SIGTERM / 15 - Terminate ◦ shutdown
  8. Divide and conquer • Goal is to establish when this

    started to happen • Remove as much as unknown as you can ◦ Issue is happening on latest version? ◦ Issue is happening on latest version minus 1 / 2 / 3 / … versions? ◦ Issue is happening on previous major version (8.0 -> 5.7) ? • ( PXB / PXC ) - Is the issue specific to the product?
  9. Divide and conquer • PXB-2742 as example: • Start Point

    - partitions -> full backup -> inc backup (one or many) -> prepare full -> prepare inc (one or many) -> crash (sometimes) • partitions ? = full backup -> inc backup (one or many) -> prepare full -> prepare inc (one or many) -> crash (sometimes)
  10. Divide and conquer • Incrementals ? = full backup ->

    prepare full -> crash (sometimes) • Investigate (prepare full): a. Innodb Master Thread Doing idle task b. Merging Insert Buffer at full io capacity ▪ Ask the pages to be read in to BP (async IO) (IO_BUF_READ) c. IO Read Thread read the page ▪ Merge Ibuf changes - Add page to Flush list d. Shutdown e. IO Read Thread complete the read/ibuf merge of page (IO_BUF_NONE)
  11. Divide and conquer • Can I reproduce the same on

    server? • DBUG_EXECUTE_IF - shutdown - full ibuf merge • Yes !!! 8.0 & 5.7 PS and upstream affected. • PS-8174 / #107069 Crash -> private =( • From a complex set of multiple variables (partition, xtrabackup, multiple incremental) to "simple" server bug. • Same mentality used while coding
  12. Regression = git bisect • PS-7019 / #99398 • Works

    ok on 8.0.19 • Does NOT work on 8.0.20
  13. Regression = git bisect mysql> SELECT * FROM t1; +-------+-------+

    | t1_id | t2_id | +-------+-------+ | 1 | 1000 | | 2 | 5 | +-------+-------+ 2 rows in set (0,00 sec) mysql> SELECT * FROM t2; +-------+-----------+ | t2_id | is_active | +-------+-----------+ | 2 | 1 | | 3 | 0 | | 1000 | 1 | +-------+-----------+ 3 rows in set (0,00 sec) 8.0.19> SELECT t1.*, t2.t2_id FROM t1 LEFT JOIN t2 ON (t1.t2_id = t2.t2_id) GROUP BY t1_id; +-------+-------+-------+ | t1_id | t2_id | t2_id | +-------+-------+-------+ | 1 | 1000 | 1000 | | 2 | 5 | NULL | +-------+-------+-------+ 2 rows in set (0,00 sec) 8.0.20> SELECT t1.*, t2.t2_id FROM t1 LEFT JOIN t2 ON (t1.t2_id = t2.t2_id) GROUP BY t1_id; +-------+-------+-------+ | t1_id | t2_id | t2_id | +-------+-------+-------+ | 1 | 1000 | NULL | | 2 | 5 | NULL | +-------+-------+-------+ 2 rows in set (0,00 sec)
  14. Regression = git bisect • Finding a Regression in MySQL

    Source Code: A Case Study • Lines (737+K): git diff mysql-8.0.19..mysql-8.0.20 | wc -l 737454 • Files (~4.5K): git diff mysql-8.0.19..mysql-8.0.20 --name-only | wc -l 4495 • Commits (~2K): git log mysql-8.0.19..mysql-8.0.20 --pretty=oneline | wc -l 1966
  15. Regression = git bisect • Manual: a. git bisect start

    mysql-8.0.20 mysql-8.0.19 b. test c. git bisect [good | bad]
  16. Regression = git bisect • Automated: git bisect run sh

    -c ' compile_mysql.sh if [ "$?" -ne "0" ]; then exit 125 fi ./mysql-test/mtr bisect if [ "$?" -eq "0" ]; then exit 0 else exit 1 fi'
  17. Regression = git bisect • Bug#30460528: RENAME FIELD::REAL_MAYBE_NULL() TO FIELD::IS_NULLABLE()

    • https://github.com/mysql/mysql-server/commit/3039fac3969f7c1521863bfe15 13631986d2b6bd
  18. GDB • GNU Debugger • Works in various languages (C

    / C++ / Go / others) • Can be used: a. Remote b. Live process - gdb -p PID c. Starting a process - gdb –args mysqld –datadir=..... d. Offline (coredump) - gdb bin/mysqld core.xxxxx
  19. GDB • Break point - stop the execution when a

    function is called. • Condition break point - same as above but with condition (var1 == value) • Watchpoints - same as break point but stop the execution when a variable is read / written / or both • Next - execute the code until the next line. • Continue - execute the code until the next break point. • Step - enter the function. • Bt - Mostrar Backtrace / Stack trace. • Frame - pular para frame especídico dentro da backtrace.
  20. Coredump • Snapshot / Dump of process memory • Used

    alongside with GDB + binary of process • Allows to check variables when the snapshot was collected • Normally collected when process crash • Can be collected on demand by gcore or gdb generate-core-file (eg: mysqld is frozen and I can't get in)
  21. Coredump • On crash: a. Requires mysqld to be configured

    with –core-file and linux config: echo 2 > /proc/sys/fs/suid_dumpable mkdir /tmp/corefiles chmod 777 /tmp/corefiles echo "/tmp/corefiles/core" > /proc/sys/kernel/core_pattern echo "1" > /proc/sys/kernel/core_uses_pid Mysqld --core-file b. PS - mysqld --coredumper=/PATH
  22. Poor Man's Profiler - PMP • Aggregates identical stack traces

    • Very useful for coredumps with high number of threads • https://poormansprofiler.org/ • Available via percona toolkit
  23. GDB / Coredump / pt-pmp • All 4996 threads are

    trying to connect and waiting on mutex from Thread 38 • Thread 38 ◦ SELECT * FROM performance_schema.session_variables WHERE VARIABLE_NAME LIKE 'binlog_transaction_dependency_tracking' ◦ Wait on mutex from Thread 44
  24. GDB / Coredump / pt-pmp • All 4996 threads are

    trying to connect and waiting on mutex from Thread 38 • Thread 38 ◦ SELECT * FROM performance_schema.session_variables WHERE VARIABLE_NAME LIKE 'binlog_transaction_dependency_tracking' ◦ Wait on mutex from Thread 44 • Thread 44 ◦ SHOW BINARY LOGS ◦ Wait on mutex from Thread 42
  25. GDB / Coredump / pt-pmp • All 4996 threads are

    trying to connect and waiting on mutex from Thread 38 • Thread 38 ◦ SELECT * FROM performance_schema.session_variables WHERE VARIABLE_NAME LIKE 'binlog_transaction_dependency_tracking' ◦ Wait on mutex from Thread 44 • Thread 44 ◦ SHOW BINARY LOGS ◦ Wait on mutex from Thread 42 • Thread 42 ◦ PURGE BINARY LOGS BEFORE NOW() ◦ Wait on mutex from Thread 38
  26. GDB / Coredump / pt-pmp • Loop in wait-for graph

    • Bug: Deadlock during purge_logs_before_date - PS-1049 #91941
  27. Record & replay • Created by Mozilla - https://rr-project.org/ •

    Open Source - https://github.com/rr-debugger/rr • Record once, replay deterministically as many times you want • Let you replay the code backwards • Run on a GDB session • Hard to reproduce bugs • Complex bugs
  28. Record & replay • Replay the Execution of MySQL With

    RR (Record and Replay) • PXB-2180 • PXB crash randomly after applying N incremental backups • Not always the same stack trace - Crash on different parts of InnoDB • Always trying to apply a record on same Space=>Page
  29. Record & replay • Page layout diverted somehow between PXB

    and Server • Crash on N th inc is a consequence of something wrong on N-M th inc. • Run MySQL under RR • Make a copy of all backups so we can re-run –prepare when the issue happens • Read the LSNs for this same page before/after each backup prepare (od). • Identify all changes to m_space = 4294967294 & m_page_no = 5 at mysqld. • Got a reproducible backup - 6th incremental was crashing
  30. Record & replay • m_space = 4294967294 correspond to the

    MySQL data dictionary (mysql.ibd) – dict0dict.h:1146 • On disk page, LSN is stored at the 16th byte of the page and has a size of 8 bytes – fil0types.h:66 • Pages are written sequentially to disk, as an example, for the default 16k page size, from bytes 1 to 16384 will have the data for page 0, from byte 16385 to 32768 data from page 1, and so on. • Frame is raw data of a page – buf0buf.h:1358
  31. Record & replay BF: 0x1102185 AF: 0x1100706 I1: 0x1231906 .

    . . I3: 0x1474d3f B: 0x15fa326 S: 0x19f3fc9
  32. Record & replay BF: 0x1102185 AF: 0x1100706 I1: 0x1231906 .

    . . I3: 0x1474d3f B: 0x15fa326 S: 0x19f3fc9