You know how to build MySQL Connector/C++ and write applications, because you have read my previous post MySQL Connector/C++: compiling, using and debugging. And, of course, its not working. therefore you try the debug trace. Are you capable of handling all the information in it? I am a lamer. The only Vi command I know is ":q".And I know nothing about sed and grep, therefore none of these can help me filtering the debug log. But I know a bit of PHP. I wrote myself a PHP script for filtering MySQL Connector/C++ debug traces when we started working on MySQL Connector/OpenOffice.org again. If you are not Andrey, this may be for you.
Andrey plays in a different league. Not only that he reads the traces like news papers because he knows every call, he also knows how to use Vi and friends However, his approach to handle several thousand lines of OOo traces has been to patch the driver itself. . Check the code of mysql_debug.cpp, if you are with him. If you do not want to do the filtering in C++ or you are concerned about modifying the source, my lamer approach might become handy.
Even if you never use the trace yourself, it would be great if you know how to enable it and send us/Support a trace upon request, for example to analyze bug reports. Please note, official support is not available for the alpha version of MySQL Connector/C++.
Fasse Dich kurz!
In the past, public phones in Germany used to have an instruction plate stating: "Fasse Dich kurz!" (Be considerate of others waiting, keep it short!). My little PHP filtering script does not understand the meaning of the words spoken by the driver and recorded in the debug trace. But if you tell it what to show using -s <pattern> or what to hide -r <pattern> it helps removing noise from the discussion between your client application and the server. And, it is capable of telling you which words and phrases occur very often in the trace log. You may want to consider some of those phrases as stop words.
Photo by tölvakonu. Published under the terms of the Creative Commons on Flickr.
DISCLAIMER
The PHP filtering script is provided as-is. I do not promise to maintain it. I do not promise to fix bugs timely. It may have bugs, buts still it may be useful not only for me. Andrey reminded me that a PHP script may not be what you really want. One may want the driver to generate valgrind compatible output to be able to utilize the numerous valgrind processors. I leave it to the Community to patch Connector/C++ to generate valgrind output. I got what I need…
A trace from examples/debug.cpp
Below you can find an example of a trace generated from the code in examples/debug.cpp. As mentioned in the previous post on building the driver all examples are compiled as part of a the normal build procedure. Currently (alpha version) trace information is always written to standard out. Redirect standard out into a file. The PHP filter script operates on files and writes its output to standard out.
nixnutz@ulflinux:~/src/connector-cpp-bzr/trunk> examples/debug
1..1
# Connector/C++ debug / client_options example..
# Test table created
| INF: Tracing enabled
<MySQL_Connection::setClientOption
>MySQL_Prepared_Statement::setInt
| INF: this=0x6a8e00
<MySQL_Prepared_Statement::setInt
>MySQL_Prepared_Statement::setString
| INF: this=0x6a8e00
<MySQL_Prepared_Statement::setString
>MySQL_Prepared_Statement::executeUpdate
| INF: this=0x6a8e00
| >MySQL_Prepared_Statement::do_query
| <MySQL_Prepared_Statement::do_query
<MySQL_Prepared_Statement::executeUpdate
>MySQL_Connection::setClientOption
| INF: Tracing enabled
<MySQL_Connection::setClientOption
>MySQL_Statement::execute
| INF: this=0x6a7210
| INF: query=DROP TABLE IF EXISTS test
| >MySQL_Statement::do_query
| | INF: this=0x6a7210
| <MySQL_Statement::do_query
<MySQL_Statement::execute
>MySQL_Prepared_Statement::~MySQL_Prepared_Statement
| >MySQL_Prepared_Statement::closeIntern
| | >MySQL_Prepared_Statement::clearParameters
| | | INF: this=0x6a8e00
| | <MySQL_Prepared_Statement::clearParameters
| <MySQL_Prepared_Statement::closeIntern
<MySQL_Prepared_Statement::~MySQL_Prepared_Statement
>MySQL_Statement::~MySQL_Statement
| INF: this=0x6a7210
<MySQL_Statement::~MySQL_Statement
>MySQL_Connection::~MySQL_Connection
<MySQL_Connection::~MySQL_Connection
ok 1
nixnutz@ulflinux:~/src/connector-cpp-bzr/trunk> examples/debug > cpp_trace.log
The PHP filter script can be found in the examples directory as well: examples/cpp_trace_analyzer.php. I run it using PHP 5.3 but any PHP version >= 5.0 should be fine. The script is not part of the Alpha release, you need to fetch the latest development snapshot from Launchpad: bzr branch lp:~mysql/mysql-connector-cpp/trunk .
If you run the script without any arguments but the name of the trace file to analyze, it prints every line from the trace file preceded by three numbers. The three columns show, from left to right, corresponding line number in the input file that belongs to this line of output, the function call nesting level (depth) and the line number in the output generated by the PHP script. For example 0000004/02/0000004 | INF: Tracing enabled tells you that you will find the string | INF: Tracing enabled in the fourth line of the trace file cpp_trace.log. The function call nesting level is considered to be two and the line number in the output file is four. Knowing the corresponding line number of the trace file becomes handy once you filter out lines.
nixnutz@ulflinux:~/src/connector-cpp-bzr/trunk> php examples/cpp_trace_analyzer.php cpp_trace.log 0000001/01/0000001 1..1 0000002/01/0000002 # Connector/C++ debug / client_options example.. 0000003/01/0000003 # Test table created 0000004/02/0000004 | INF: Tracing enabled 0000005/01/0000005 <MySQL_Connection::setClientOption 0000006/01/0000006 >MySQL_Prepared_Statement::setInt [...] 0000039/01/0000039 ok 1
How to know what to filter out?
To identify classes or methods to filter out from the trace for better "readability" you advice the filter script to generate call statistics by passing the options -stats to the script. At the end of the statistics you can see how many percent of the input have been hidden by filters. You also get hints how to hide individual methods that make more than 2% of all function calls.
nixnutz@ulflinux:~/src/connector-cpp-bzr/trunk> php examples/cpp_trace_analyzer.php -stats cpp_trace.log [...] 0000039/01/0000039 ok 1 Class: MySQL_Connection ~MySQL_Connection 2 (= 9.09%) - (shown, use "-r MySQL_Connection::~MySQL_Connection" to hide) setClientOption 2 (= 9.09%) - (shown, use "-r MySQL_Connection::setClientOption" to hide) Class: MySQL_Prepared_Statement (shown, use "-r MySQL_Connection::setClientOption" to hide) clearParameters 2 (= 9.09%) - (shown, use "-r MySQL_Prepared_Statement::clearParameters" to hide) setInt 2 (= 9.09%) - (shown, use "-r MySQL_Prepared_Statement::setInt" to hide) executeUpdate 2 (= 9.09%) - (shown, use "-r MySQL_Prepared_Statement::executeUpdate" to hide) setString 2 (= 9.09%) - (shown, use "-r MySQL_Prepared_Statement::setString" to hide) closeIntern 1 (= 4.55%) - (shown, use "-r MySQL_Prepared_Statement::closeIntern" to hide) do_query 1 (= 4.55%) - (shown, use "-r MySQL_Prepared_Statement::do_query" to hide) ~MySQL_Prepared_Statement 1 (= 4.55%) - (shown, use "-r MySQL_Prepared_Statement::~MySQL_Prepared_Statement" to hide) Class: MySQL_Statement (shown, use "-r MySQL_Prepared_Statement::~MySQL_Prepared_Statement" to hide) execute 3 (= 13.64%) - (shown, use "-r MySQL_Statement::execute" to hide) ~MySQL_Statement 2 (= 9.09%) - (shown, use "-r MySQL_Statement::~MySQL_Statement" to hide) do_query 2 (= 9.09%) - (shown, use "-r MySQL_Statement::do_query" to hide) NOTE: 0.00% of all calls hidden. If you want to hide all functions which are invoked in more than 2% of all cases, use: -r MySQL_Connection::~MySQL_Connection -r MySQL_Connection::setClientOption -r MySQL_Prepared_Statement::clearParameters -r MySQL_Prepared_Statement::setInt -r MySQL_Prepared_Statement::executeUpdate -r MySQL_Prepared_Statement::setString -r MySQL_Prepared_Statement::closeIntern -r MySQL_Prepared_Statement::do_query -r MySQL_Prepared_Statement::~MySQL_Prepared_Statement -r MySQL_Statement::execute -r MySQL_Statement::~MySQL_Statement -r MySQL_Statement::do_query
The example is quite boring because the trace has only 39 lines. But when developing a larger application or when performing some actions in OpenOffice.org Base while developing Connector/OpenOffice.org, you trace can easily have 302.880 lines. Regardless of how many lines your trace has the statistics give you a second benefit: you get a first overview what is going on.
0302877/01/0302874 OConnection::isClosed 0302878/01/0302875 >MySQL_Connection::~MySQL_Connection 0302879/01/0302876 <MySQL_Connection::~MySQL_Connection 0302880/01/0302877 MysqlCDriver::disposing Class: MySQL_Connection checkClosed 1118 (= 0.58%) - (shown) getMySQLHandle 588 (= 0.30%) - (shown) createStatement 303 (= 0.16%) - (shown) getSessionVariable 276 (= 0.14%) - (shown) prepareStatement 100 (= 0.05%) - (shown) getMetaData 33 (= 0.02%) - (shown) MySQL_Connection 5 (= 0.00%) - (shown) ~MySQL_Connection 4 (= 0.00%) - (shown) setAutoCommit 4 (= 0.00%) - (shown) setTransactionIsolation 4 (= 0.00%) - (shown) isClosed 2 (= 0.00%) - (shown) Class: MySQL_ConnectionMetaData (shown) getIdentifierQuoteString 33 (= 0.02%) - (shown) MySQL_ConnectionMetaData 33 (= 0.02%) - (shown) getColumns 32 (= 0.02%) - (shown) getPrimaryKeys 28 (= 0.01%) - (shown) getTables 20 (= 0.01%) - (shown) ~MySQL_ConnectionMetaData 6 (= 0.00%) - (shown) getDatabasePatchVersion 4 (= 0.00%) - (shown) getDatabaseMinorVersion 4 (= 0.00%) - (shown) getDatabaseMajorVersion 4 (= 0.00%) - (shown) supportsMixedCaseQuotedIdentifiers 2 (= 0.00%) - (shown) isCatalogAtStart 1 (= 0.00%) - (shown) getCatalogSeparator 1 (= 0.00%) - (shown) supportsCatalogsInDataManipulation 1 (= 0.00%) - (shown) usesLocalFiles 1 (= 0.00%) - (shown) usesLocalFilePerTable 1 (= 0.00%) - (shown) getMaxTablesInSelect 1 (= 0.00%) - (shown) supportsSchemasInDataManipulation 1 (= 0.00%) - (shown) Class: MySQL_ConstructedResultSet (shown) isBeforeFirstOrAfterLast 53922 (= 27.87%) - (shown, use "-r MySQL_ConstructedResultSet::isBeforeFirstOrAfterLast" to hide) getString(int) 36443 (= 18.84%) - (shown, use "-r MySQL_ConstructedResultSet::getString(int)" to hide) isClosed 20232 (= 10.46%) - (shown, use "-r MySQL_ConstructedResultSet::isClosed" to hide) checkValid 20232 (= 10.46%) - (shown, use "-r MySQL_ConstructedResultSet::checkValid" to hide) isLast 3087 (= 1.60%) - (shown) next 1077 (= 0.56%) - (shown) afterLast 208 (= 0.11%) - (shown) MySQL_ConstructedResultSet 140 (= 0.07%) - (shown) first 116 (= 0.06%) - (shown) seek 109 (= 0.06%) - (shown) getMetaData 70 (= 0.04%) - (shown) Class: MySQL_ConstructedResultSetMetaData (shown) getColumnCount 210 (= 0.11%) - (shown) ~MySQL_ConstructedResultSetMetaData 140 (= 0.07%) - (shown) Class: MySQL_Prepared_ResultSet (shown) isBeforeFirstOrAfterLast 1246 (= 0.64%) - (shown) getString(int) 856 (= 0.44%) - (shown) checkValid 636 (= 0.33%) - (shown) isLast 480 (= 0.25%) - (shown) next 344 (= 0.18%) - (shown) MySQL_Prepared_ResultSet 108 (= 0.06%) - (shown) closeIntern 72 (= 0.04%) - (shown) ~MySQL_Prepared_ResultSet 72 (= 0.04%) - (shown) Class: MySQL_Prepared_Statement (shown) setString 144 (= 0.07%) - (shown) checkClosed 108 (= 0.06%) - (shown) executeQuery 72 (= 0.04%) - (shown) closeIntern 36 (= 0.02%) - (shown) ~MySQL_Prepared_Statement 36 (= 0.02%) - (shown) bindResult 36 (= 0.02%) - (shown) do_query 36 (= 0.02%) - (shown) MySQL_Prepared_Statement 36 (= 0.02%) - (shown) Class: MySQL_ResultSet (shown) isBeforeFirstOrAfterLast 8846 (= 4.57%) - (shown, use "-r MySQL_ResultSet::isBeforeFirstOrAfterLast" to hide) getString(int) 6200 (= 3.20%) - (shown, use "-r MySQL_ResultSet::getString(int)" to hide) isClosed 4096 (= 2.12%) - (shown, use "-r MySQL_ResultSet::isClosed" to hide) checkValid 3884 (= 2.01%) - (shown, use "-r MySQL_ResultSet::checkValid" to hide) isLast 1122 (= 0.58%) - (shown) next 829 (= 0.43%) - (shown) afterLast 496 (= 0.26%) - (shown) MySQL_ResultSet 466 (= 0.24%) - (shown) ~MySQL_ResultSet 445 (= 0.23%) - (shown) getMetaData 64 (= 0.03%) - (shown) Class: MySQL_ResultSetMetaData (shown) getColumnDisplaySize 1872 (= 0.97%) - (shown) isNullable 1872 (= 0.97%) - (shown) getColumnCount 996 (= 0.51%) - (shown) getScale 936 (= 0.48%) - (shown) getColumnTypeName 936 (= 0.48%) - (shown) getColumnType 936 (= 0.48%) - (shown) MySQL_ResultSetMetaData 32 (= 0.02%) - (shown) Class: MySQL_Statement (shown) executeQuery 897 (= 0.46%) - (shown) checkClosed 776 (= 0.40%) - (shown) do_query 614 (= 0.32%) - (shown) MySQL_Statement 606 (= 0.31%) - (shown) ~MySQL_Statement 606 (= 0.31%) - (shown) get_resultset 466 (= 0.24%) - (shown) executeUpdate 16 (= 0.01%) - (shown) Class: MysqlCDriver (shown) acceptsURL 119 (= 0.06%) - (shown) connect 4 (= 0.00%) - (shown) disposing 3 (= 0.00%) - (shown) getPropertyInfo 3 (= 0.00%) - (shown) getSupportedServiceNames_Static 3 (= 0.00%) - (shown) MysqlCDriver 3 (= 0.00%) - (shown) getImplementationName_Static 3 (= 0.00%) - (shown) Class: OConnection (shown) release 389 (= 0.20%) - (shown) getMetaData 303 (= 0.16%) - (shown) getConnection 69 (= 0.04%) - (shown) createStatement 66 (= 0.03%) - (shown) prepareStatement 14 (= 0.01%) - (shown) getMysqlVersion 10 (= 0.01%) - (shown) clearWarnings 5 (= 0.00%) - (shown) getWarnings 5 (= 0.00%) - (shown) ~OConnection 4 (= 0.00%) - (shown) disposing 4 (= 0.00%) - (shown) OConnection 4 (= 0.00%) - (shown) construct 4 (= 0.00%) - (shown) isClosed 4 (= 0.00%) - (shown) close 3 (= 0.00%) - (shown) Class: ODatabaseMetaData (shown) supportsSchemasInDataManipulation 272 (= 0.14%) - (shown) supportsCatalogsInDataManipulation 272 (= 0.14%) - (shown) getIdentifierQuoteString 239 (= 0.12%) - (shown) getCatalogSeparator 195 (= 0.10%) - (shown) isCatalogAtStart 167 (= 0.09%) - (shown) isReadOnly 148 (= 0.08%) - (shown) getMaxTablesInSelect 37 (= 0.02%) - (shown) supportsMixedCaseQuotedIdentifiers 36 (= 0.02%) - (shown) getColumns 32 (= 0.02%) - (shown) getPrimaryKeys 28 (= 0.01%) - (shown) storesMixedCaseQuotedIdentifiers 20 (= 0.01%) - (shown) getURL 12 (= 0.01%) - (shown) getTables 10 (= 0.01%) - (shown) supportsAlterTableWithDropColumn 4 (= 0.00%) - (shown) supportsAlterTableWithAddColumn 4 (= 0.00%) - (shown) ~ODatabaseMetaData 3 (= 0.00%) - (shown) getTableTypes 3 (= 0.00%) - (shown) usesLocalFiles 3 (= 0.00%) - (shown) ODatabaseMetaData 3 (= 0.00%) - (shown) usesLocalFilePerTable 3 (= 0.00%) - (shown) getExtraNameCharacters 2 (= 0.00%) - (shown) Class: OStatement (shown) acquire 2092 (= 1.08%) - (shown) release 2092 (= 1.08%) - (shown) queryInterface 566 (= 0.29%) - (shown) Class: OStatement_BASE2 (shown) release 2092 (= 1.08%) - (shown) disposing 66 (= 0.03%) - (shown) Class: OStatement_Base (shown) acquire 2092 (= 1.08%) - (shown) queryInterface 566 (= 0.29%) - (shown) getInfoHelper 132 (= 0.07%) - (shown) close 66 (= 0.03%) - (shown) executeQuery 66 (= 0.03%) - (shown) convertFastPropertyValue 66 (= 0.03%) - (shown) OStatement_Base 66 (= 0.03%) - (shown) disposeResultSet 66 (= 0.03%) - (shown) createArrayHelper 2 (= 0.00%) - (shown) NOTE: 0.00% of all calls hidden. If you want to hide all functions which are invoked in more than 2% of all cases, use: -r MySQL_ConstructedResultSet::isBeforeFirstOrAfterLast -r MySQL_ConstructedResultSet::getString(int) -r MySQL_ConstructedResultSet::isClosed -r MySQL_ConstructedResultSet::checkValid -r MySQL_ResultSet::isBeforeFirstOrAfterLast -r MySQL_ResultSet::getString(int) -r MySQL_ResultSet::isClosed -r MySQL_ResultSet::checkValid
Filtering out calls from the trace
When debugging you often have a first idea where the issue might be. For example, you may want to ignore everything that is related to establishing a connection. Most connection related methods are found in the driver class MySQL_Connection. You can use -r MySQL_Connection:: to hide each and every call to any method of the class. Or you use -r MySQL_Connection::setClientOption to hide calls of the method setClientOption of the class MySQL_Connection. Alternatively you may also try -r setClientOption to hide calls of the method setClientOption of any class.
Let filter out all calls of all methods from the class MySQL_Connection using the syntax shown below. Note how the output of the filter script becomes shorter and note also the gaps in the line numbering of the input file, for example, input line number five is missing. If you distrust the filter logic, add -v to the option list to increase the verbosity of the script.
ixnutz@ulflinux:~/src/connector-cpp-bzr/trunk> php examples/cpp_trace_analyzer.php -r MySQL_Connection:: -stats cpp_trace.log 0000001/01/0000001 1..1 0000002/01/0000002 # Connector/C++ debug / client_options example.. 0000003/01/0000003 # Test table created 0000004/02/0000004 | INF: Tracing enabled 0000006/01/0000005 >MySQL_Prepared_Statement::setInt 0000007/02/0000006 | INF: this=0x6a8e00 0000008/01/0000007 <MySQL_Prepared_Statement::setInt 0000009/01/0000008 >MySQL_Prepared_Statement::setString 0000010/02/0000009 | INF: this=0x6a8e00 0000011/01/0000010 <MySQL_Prepared_Statement::setString 0000012/01/0000011 >MySQL_Prepared_Statement::executeUpdate 0000013/02/0000012 | INF: this=0x6a8e00 0000014/02/0000013 | >MySQL_Prepared_Statement::do_query 0000015/02/0000014 | <MySQL_Prepared_Statement::do_query 0000016/01/0000015 <MySQL_Prepared_Statement::executeUpdate 0000020/01/0000016 >MySQL_Statement::execute 0000021/02/0000017 | INF: this=0x6a7210 0000022/02/0000018 | INF: query=DROP TABLE IF EXISTS test 0000023/02/0000019 | >MySQL_Statement::do_query 0000024/05/0000020 | | INF: this=0x6a7210 0000025/02/0000021 | <MySQL_Statement::do_query 0000026/01/0000022 <MySQL_Statement::execute 0000027/01/0000023 >MySQL_Prepared_Statement::~MySQL_Prepared_Statement 0000028/02/0000024 | >MySQL_Prepared_Statement::closeIntern 0000029/05/0000025 | | >MySQL_Prepared_Statement::clearParameters 0000030/08/0000026 | | | INF: this=0x6a8e00 0000031/05/0000027 | | <MySQL_Prepared_Statement::clearParameters 0000032/02/0000028 | <MySQL_Prepared_Statement::closeIntern 0000033/01/0000029 <MySQL_Prepared_Statement::~MySQL_Prepared_Statement 0000034/01/0000030 >MySQL_Statement::~MySQL_Statement 0000035/02/0000031 | INF: this=0x6a7210 0000036/01/0000032 <MySQL_Statement::~MySQL_Statement Class: MySQL_Connection (hidden because of -r MySQL_Connection::) ~MySQL_Connection 2 (= 9.09%) - (hidden because of -r MySQL_Connection::) setClientOption 2 (= 9.09%) - (hidden because of -r MySQL_Connection::) Class: MySQL_Prepared_Statement (shown) clearParameters 2 (= 9.09%) - (shown, use "-r MySQL_Prepared_Statement::clearParameters" to hide) setInt 2 (= 9.09%) - (shown, use "-r MySQL_Prepared_Statement::setInt" to hide) executeUpdate 2 (= 9.09%) - (shown, use "-r MySQL_Prepared_Statement::executeUpdate" to hide) setString 2 (= 9.09%) - (shown, use "-r MySQL_Prepared_Statement::setString" to hide) closeIntern 1 (= 4.55%) - (shown, use "-r MySQL_Prepared_Statement::closeIntern" to hide) do_query 1 (= 4.55%) - (shown, use "-r MySQL_Prepared_Statement::do_query" to hide) ~MySQL_Prepared_Statement 1 (= 4.55%) - (shown, use "-r MySQL_Prepared_Statement::~MySQL_Prepared_Statement" to hide) Class: MySQL_Statement (shown) execute 3 (= 13.64%) - (shown, use "-r MySQL_Statement::execute" to hide) ~MySQL_Statement 2 (= 9.09%) - (shown, use "-r MySQL_Statement::~MySQL_Statement" to hide) do_query 2 (= 9.09%) - (shown, use "-r MySQL_Statement::do_query" to hide) NOTE: 18.18% of all calls hidden. If you want to hide all functions which are invoked in more than 2% of all cases, use: -r MySQL_Prepared_Statement::clearParameters -r MySQL_Prepared_Statement::setInt -r MySQL_Prepared_Statement::executeUpdate -r MySQL_Prepared_Statement::setString -r MySQL_Prepared_Statement::closeIntern -r MySQL_Prepared_Statement::do_query -r MySQL_Prepared_Statement::~MySQL_Prepared_Statement -r MySQL_Statement::execute -r MySQL_Statement::~MySQL_Statement -r MySQL_Statement::do_query nixnutz@ulflinux:~/src/connector-cpp-bzr/trunk> php examples/cpp_trace_analyzer.php -r MySQL_Connection:: -v cpp_trace.log 0000001/01/0000001 1..1 0000002/01/0000002 # Connector/C++ debug / client_options example.. 0000003/01/0000003 # Test table created 0000004/02/0000004 | INF: Tracing enabled 0000005 - Skip - class MySQL_Connection because of -r MySQL_Connection:: 0000006/01/0000005 >MySQL_Prepared_Statement::setInt [...]
Show something, hide the rest
The inverse of -r <pattern> is -s <pattern>. Lets assume you changed your mind and you want to see only the calls to methods from the MySQL_Connection class. Or what about showing all queries run through MySQL_Statement::execute?
nixnutz@ulflinux:~/src/connector-cpp-bzr/trunk> php examples/cpp_trace_analyzer.php -s MySQL_Connection:: cpp_trace.log 0000005/01/0000001 <MySQL_Connection::setClientOption 0000017/01/0000002 >MySQL_Connection::setClientOption 0000018/02/0000003 | INF: Tracing enabled 0000019/01/0000004 <MySQL_Connection::setClientOption 0000037/01/0000005 >MySQL_Connection::~MySQL_Connection 0000038/01/0000006 <MySQL_Connection::~MySQL_Connection 0000039/01/0000007 ok 1 nixnutz@ulflinux:~/src/connector-cpp-bzr/trunk> php examples/cpp_trace_analyzer.php -s MySQL_Statement::execute cpp_trace.log 0000020/01/0000001 >MySQL_Statement::execute 0000021/02/0000002 | INF: this=0x6a7210 0000022/02/0000003 | INF: query=DROP TABLE IF EXISTS test 0000026/01/0000004 <MySQL_Statement::execute
What else? -c, -l
The last two important switches are -c and -l <depth>. -c does compress the entering and exiting message of a function into one line if there is nothing in between the entering and exiting message. -l limits the function call nesting level in the output. If, for example, function A calls function B then A is given the nesting level 1 and B gets nesting level 2. By using -l 1 you could hide function B from the trace.
nixnutz@ulflinux:~/src/connector-cpp-bzr/trunk> php examples/cpp_trace_analyzer.php -l 1 cpp_trace.log 0000001/01/0000001 1..1 0000002/01/0000002 # Connector/C++ debug / client_options example.. 0000003/01/0000003 # Test table created 0000005/01/0000004 <MySQL_Connection::setClientOption 0000006/01/0000005 >MySQL_Prepared_Statement::setInt 0000008/01/0000006 <MySQL_Prepared_Statement::setInt 0000009/01/0000007 >MySQL_Prepared_Statement::setString 0000011/01/0000008 <MySQL_Prepared_Statement::setString 0000012/01/0000009 >MySQL_Prepared_Statement::executeUpdate 0000016/01/0000010 <MySQL_Prepared_Statement::executeUpdate 0000017/01/0000011 >MySQL_Connection::setClientOption 0000019/01/0000012 <MySQL_Connection::setClientOption 0000020/01/0000013 >MySQL_Statement::execute 0000026/01/0000014 <MySQL_Statement::execute 0000027/01/0000015 >MySQL_Prepared_Statement::~MySQL_Prepared_Statement 0000033/01/0000016 <MySQL_Prepared_Statement::~MySQL_Prepared_Statement 0000034/01/0000017 >MySQL_Statement::~MySQL_Statement 0000036/01/0000018 <MySQL_Statement::~MySQL_Statement 0000037/01/0000019 >MySQL_Connection::~MySQL_Connection 0000038/01/0000020 <MySQL_Connection::~MySQL_Connection 0000039/01/0000021 ok 1 nixnutz@ulflinux:~/src/connector-cpp-bzr/trunk> php examples/cpp_trace_analyzer.php -c cpp_trace.log 0000001/01/0000001 1..1 0000002/01/0000002 # Connector/C++ debug / client_options example.. 0000003/01/0000003 # Test table created 0000004/02/0000004 | INF: Tracing enabled 0000005/01/0000005 <MySQL_Connection::setClientOption 0000006/01/0000006 >MySQL_Prepared_Statement::setInt 0000007/02/0000007 | INF: this=0x6a8e00 0000008/01/0000008 <MySQL_Prepared_Statement::setInt 0000009/01/0000009 >MySQL_Prepared_Statement::setString 0000010/02/0000010 | INF: this=0x6a8e00 0000011/01/0000011 <MySQL_Prepared_Statement::setString 0000012/01/0000012 >MySQL_Prepared_Statement::executeUpdate 0000013/02/0000013 | INF: this=0x6a8e00 0000015/02/0000014 | =MySQL_Prepared_Statement::do_query 0000016/01/0000015 <MySQL_Prepared_Statement::executeUpdate
Ok, in real life I use a mixture of grep and the PHP script, but still, I am a Unix command line lamer… Greetings to all super heroes and nixnutze!