| Bug #96826 | DBUG_PRINTs are lost | ||
|---|---|---|---|
| Submitted: | 10 Sep 2019 16:02 | Modified: | 15 Nov 2019 12:26 |
| Reporter: | Tony Reix | Email Updates: | |
| Status: | Not a Bug | Impact on me: | |
| Category: | MySQL Server | Severity: | S6 (Debug Builds) |
| Version: | 8.0.16 | OS: | Fedora (fc30) |
| Assigned to: | CPU Architecture: | POWER (PPC64LE) | |
[10 Sep 2019 16:04]
Tony Reix
Debug-patched sql_table.cc file
Attachment: sql_table.cc (text/x-c++src), 693.10 KiB.
[11 Sep 2019 10:12]
Tor Didriksen
did you try to turn on flush-on-write for the dbug system?
[11 Sep 2019 10:35]
Tony Reix
No. I had no idea such feature does exist. However, looking for this feature, I was unable to find any hints about it on the Web, in the code, or in all source code. Would you mind providing some help/explanation about how I can put this flush-on-write at work? Thx
[11 Sep 2019 10:37]
Tor Didriksen
I don't use the DBUG system myself anymore, but I found some documentation here: https://dev.mysql.com/doc/refman/5.7/en/dbug-package.html
[11 Sep 2019 14:05]
Tony Reix
Thx.
I used: ./mtr .... --debug --mysqltest=d:t:i:O,/tmp/mysqld.trace
which generated :
mysql-test/mysql-test-run.pl --warnings --verbose \
--debug --mysqltest=d:t:i:O,/tmp/mysqld.trace \
--parallel=1 --force --retry=0 --suite-timeout=2000 --testcase-timeout=60 --report-unstable-tests --max-save-core=100 --max-test-fail=0 --tmpdir=/My --user=root --mark-progress innodb.innodb-import-partition
However, the test was run with:
build/runtime_output_directory/mysqltest_safe_process --verbose -- /opt/freeware/src/packages/BUILD/mysql-8.0.16-1/build/runtime_output_directory/mysqld-debug --defaults-group-suffix=.1 --defaults-file=/opt/freeware/src/packages/BUILD/mysql-8.0.16-1/build/mysql-test/var/my.cnf --user=root --log-output=file --loose-debug-sync-timeout=600 --core-file
--debug=d:t:i:A,/opt/freeware/src/packages/BUILD/mysql-8.0.16-1/build/mysql-test/var/log/mysqld.1.trace
and thus the options I provided were not taken into account.
Worse, I no more had my traces...
If I use : ./mtr ... --debug --mysqld=d:t:i:O,/tmp/mysqld.trace
(mysqld instead of mysqltest)
the test breaks at launch.
Hummm I may have done mistakes... Not really sure. Probably I missed something or these options no more work.
[11 Sep 2019 14:37]
Tor Didriksen
this seems to work for me: ./mtr --mem --mysqld=--debug=d:t:i:O,/tmp/mysqld.trace main.1st Logging: ...../mysql-test/mysql-test-run.pl --mem --mysqld=--debug=d:t:i:O,/tmp/mysqld.trace main.1st MySQL Version 8.0.19
[11 Sep 2019 15:14]
Tony Reix
Ooops ! My mistake. I wrote : ./mtr .... --debug --mysqltest=d:t:i:O,/tmp/mysqld.trace instead of: ./mtr .... --mysqld=--debug=d:t:i:O,/tmp/mysqld.trace However, now I have: Logging: /opt/freeware/src/packages/BUILD/mysql-8.0.16-1/mysql-test/mysql-test-run.pl --warnings --verbose --debug --mysqld=--debug=d:t:i:O,/tmp/mysqld.trace --parallel=1 --force --retry=0 --suite-timeout=2000 --testcase-timeout=60 --report-unstable-tests --max-save-core=100 --max-test-fail=0 --tmpdir=/My --user=root --mark-progress innodb.innodb-import-partition (in short : .../mysql-test/mysql-test-run.pl ... --debug --mysqld=--debug=d:t:i:O,/tmp/mysqld.trace ....) ... ### safe_path: .../build/runtime_output_directory/mysqltest_safe_process ..... --debug=d:t:i:A,/opt/freeware/src/packages/BUILD/mysql-8.0.16-1/build/mysql-test/var/log/bootstrap.trace ...... ... ### safe_path: .../build/runtime_output_directory/mysqltest_safe_process ..... --debug=d:t:i:A,/opt/freeware/src/packages/BUILD/mysql-8.0.16-1/build/mysql-test/var/log/mysqld.1.trace ...... ... ### safe_path: .../build/runtime_output_directory/mysqltest_safe_process ... --debug=d:t:i:O,/tmp/mysqld.trace .... --debug=d:t:i:A,/opt/freeware/src/packages/BUILD/mysql-8.0.16-1/build/mysql-test/var/log/mysqld.1.trace ... THUS : 2 times x --debug= option ! Last one is used I think. And thus: ll /tmp/mysqld.trace -rw-rw---- 1 root root 0 11 sept. 17:01 /tmp/mysqld.trace And in .../build/mysql-test/var/log/mysqld.1.trace I still miss many debug lines.
[12 Sep 2019 5:55]
Tor Didriksen
don't use --debug for mtr, in mysqld_start it will do:
if ($opt_debug) {
mtr_add_arg($args, "--debug=$debug_d:t:i:A,%s/log/%s.trace",
$path_vardir_trace, $mysqld->name());
}
thus overriding your --debug option
[13 Sep 2019 12:50]
Tony Reix
I have patched the file: mysql-test/mysql-test-run.pl so that I have now: --debug=$debug_d:t:i:O instead of: --debug=$debug_d:t:i:A I see that it does: ### safe_path: /opt/freeware/src/packages/BUILD/mysql-8.0.16-1/build/runtime_output_directory/mysqltest_safe_process --verbose .... \ --debug=d:t:i:O,/tmp/mysqld.trace --core-file \ --debug=d:t:i:O,/opt/freeware/src/packages/BUILD/mysql-8.0.16-1/build/mysql-test/var/log/mysqld.1.trace However, in mysqld.1.trace, I still see 208 times the line with trace "6a2" but only 26 times the line with trace "6a1", though there should be the exact same number. Lines of trace disappear (only on Fedora/PPC64LE. That's OK on AIX).
[14 Oct 2019 12:53]
MySQL Verification Team
Hi Mr. Reix, This is a forum for bugs in the unchanged MySQL products. If you can report any of our DBUG_PRINTs not working, we would be happy to help you. The problem may lie with the compiler that you are using. It is possible that it does not accept quoted arguments in the functions with variable arguments.
[15 Nov 2019 1:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".
Description: In my Environment (Fedora 30 on PPC64LE) with 32 virtual processors, the DBUG_PRINT() utility is not reliable : many DBUG_PRINT() lines are not logged into the build/mysql-test/var/log/mysqld.1.trace file. This is reproducible in this environment. It does not occur on AIX (less processors). I guess that the mechanisme used for locking is not reliable when many processors are available. MySQL built in DEBUG mode plus --debug when testing. How to repeat: I have instrumented the sql/sql_table.cc file with many additional DBUG_PRINT() instructions in order to understand an issue I had with AIX stpncpy() routine. I'll attach the file. In the following: DBUG_PRINT("TONY 6a1 part_name - explain_mode == EXPLAIN_PARTITIONS_AS_COMMENT Bf my_stpncpy", ("to_p: '%p' '%s' end_p: '%p' '%s' end_p - to_p: '%ld'", to_p, to_p, end_p, end_p, end_p - to_p)); to_p = my_stpncpy(to_p, " /* ", end_p - to_p); DBUG_PRINT("TONY 6a2 part_name - explain_mode == EXPLAIN_PARTITIONS_AS_COMMENT Af my_stpncpy", ("to_p: '%p' '%s' ", to_p, to_p)); it appears that the line "TONY 6a2" nearly always appears though the line "TONY 6a1" appears about only 1 out of 10 expected ones. Same in other places (10a1 / 10a2).