Skip to content

Commit ac8271c

Browse files
mfulbmfulb
authored
fix(agent): Fixes warning from mysqli when explaining slow SQL queries (GH issue 875) (#881)
In GH issue #875 it was reported a warning is generated when using prepared statements with `mysqli`. The issue included excellent instructions on how to reproduce the issue. This PR addresses the cause of the warning. To understand the cause of the warning requires understanding how the agent handles `mysqli::stmt` objects. When a SQL statement is prepared via mysqli the agent will store the SQL string in a global hashmap called `mysqli_queries` *if* the SQL is considered explainable (determined via `nr_php_explain_mysql_query_is_explainable()`), otherwise it is just ignored. Later when a slow SQL query is detected the SQL string is retrieved and used to explain the query. An additional factor is when a `mysqli::stmt` object is released it goes into a free pool PHP keeps which allows it to quickly hand out an allocated section of memory when a new object is created. Each object has a `object ID` (referenced as a `handle` in the agent for the relevant code). When an the allocated object is reused from the free pool it retains the same `object ID`. The agent used the `object ID` (`handle`) as the key for storing the prepared SQL string for explainable SQL strings. Now what if an explainable query comes through, the string is stored, and then that object is released. A new query is prepared with a string that is NOT explainable and gets the object container with the same `object ID` as the explainable one just released. The string stored in `mysqli_queries` using that `object ID` as the key is now stale. If the new, unexplainable query is slow then the agent will pull this stale string and try to run an explain with it - leading to the warning. The fix is to clear any query string for a given `object ID` if the query string is unexplainable. Integration tests were added (based on the reproduction case) that test for a regression of this fix.
1 parent 7c985b8 commit ac8271c

File tree

5 files changed

+350
-7
lines changed

5 files changed

+350
-7
lines changed

‎agent/php_internal_instrument.c

Lines changed: 16 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -1358,15 +1358,24 @@ static void nr_php_prepared_prepare_general(INTERNAL_FUNCTION_PARAMETERS,
13581358
nr_php_prepared_statement_save(return_value, extension, sqlstr,
13591359
sqlstrlen TSRMLS_CC);
13601360

1361+
/* Record the current query link and SQL string if the right conditions exist
1362+
* Note if the SQL string is not explainable then the previous recorded query
1363+
* string (from the query previously using the same handle) needs to be
1364+
* cleared so that the previous string is not errantly retrieved and "EXPLAIN"
1365+
* run with it
1366+
*/
1367+
13611368
if ((0 == NRTXNGLOBAL(generating_explain_plan))
1362-
&& nr_php_mysqli_zval_is_stmt(return_value TSRMLS_CC)
1363-
&& nr_php_mysqli_zval_is_link(conn_obj TSRMLS_CC)
1364-
&& nr_php_explain_mysql_query_is_explainable(sqlstr, sqlstrlen)) {
1365-
nr_php_mysqli_query_set_link(Z_OBJ_HANDLE_P(return_value),
1366-
conn_obj TSRMLS_CC);
1369+
&& nr_php_mysqli_zval_is_stmt(return_value)
1370+
&& nr_php_mysqli_zval_is_link(conn_obj)) {
1371+
nr_php_mysqli_query_set_link(Z_OBJ_HANDLE_P(return_value), conn_obj);
13671372

1368-
nr_php_mysqli_query_set_query(Z_OBJ_HANDLE_P(return_value), sqlstr,
1369-
sqlstrlen TSRMLS_CC);
1373+
if (nr_php_explain_mysql_query_is_explainable(sqlstr, sqlstrlen)) {
1374+
nr_php_mysqli_query_set_query(Z_OBJ_HANDLE_P(return_value), sqlstr,
1375+
sqlstrlen);
1376+
} else {
1377+
nr_php_mysqli_query_clear_query(Z_OBJ_HANDLE_P(return_value));
1378+
}
13701379
}
13711380
}
13721381

‎agent/php_mysqli.c

Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -353,6 +353,31 @@ nr_status_t nr_php_mysqli_query_set_query(nr_php_object_handle_t handle,
353353
return NR_SUCCESS;
354354
}
355355

356+
nr_status_t nr_php_mysqli_query_clear_query(nr_php_object_handle_t handle) {
357+
zval* metadata = NULL;
358+
359+
/* If a metadata entry exists then clear the "query" tag from it.
360+
* If an entry does not exist then nothing needs to be done.
361+
*/
362+
metadata = nr_php_mysqli_query_find(handle);
363+
if (NULL == metadata) {
364+
return NR_FAILURE;
365+
}
366+
367+
/* Clear the "query" element */
368+
nr_php_zend_hash_del(Z_ARRVAL_P(metadata), "query");
369+
370+
/*
371+
* Since the query is cleared so must the bind parameters, so let's get rid of
372+
* whatever's here. We'll ignore the return values, since if the keys don't
373+
* already exist no harm is done.
374+
*/
375+
nr_php_zend_hash_del(Z_ARRVAL_P(metadata), "bind_args");
376+
nr_php_zend_hash_del(Z_ARRVAL_P(metadata), "bind_format");
377+
378+
return NR_SUCCESS;
379+
}
380+
356381
int nr_php_mysqli_zval_is_link(const zval* zv TSRMLS_DC) {
357382
if (NULL == zv) {
358383
return 0;

‎agent/php_mysqli.h

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -87,6 +87,15 @@ extern nr_status_t nr_php_mysqli_query_set_link(
8787
nr_php_object_handle_t query_handle,
8888
zval* link TSRMLS_DC);
8989

90+
/*
91+
* Purpose : Clear the SQL used to prepare a MySQLi statement.
92+
*
93+
* Params : 1. The object handle of the statement.
94+
*
95+
* Returns : NR_SUCCESS or NR_FAILURE.
96+
*/
97+
extern nr_status_t nr_php_mysqli_query_clear_query(nr_php_object_handle_t handle);
98+
9099
/*
91100
* Purpose : Save the SQL used to prepare a MySQLi statement.
92101
*

‎tests/integration/mysqli/test_explain_reused_id_multiple_001.php

Lines changed: 124 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,124 @@
1+
<?php
2+
/*
3+
* Copyright 2020 New Relic Corporation. All rights reserved.
4+
* SPDX-License-Identifier: Apache-2.0
5+
*/
6+
7+
/*DESCRIPTION
8+
The agent should generate explain plans even when object IDs are reused
9+
and some of the SQL strings are not explainable. This tests that if
10+
a object ID is reused and a new mysqli::stmt object is created with an
11+
unexplainable SQL string that the "mysqli_entries" entry for this
12+
object ID ("handle") has it "query" parameter cleared. This prevents
13+
using an older, stale "query" parameter (from a myqsli::stmt object
14+
which was reclaimed by PHP) being using incorrectly with a newer query.
15+
*/
16+
17+
/*SKIPIF
18+
<?php
19+
require("skipif.inc");
20+
*/
21+
22+
/*INI
23+
newrelic.transaction_tracer.explain_enabled = true
24+
newrelic.transaction_tracer.explain_threshold = 500
25+
newrelic.transaction_tracer.record_sql = obfuscated
26+
*/
27+
28+
/*
29+
30+
[
31+
[
32+
[
33+
"OtherTransaction/php__FILE__",
34+
"\u003cunknown\u003e",
35+
"??",
36+
"SELECT TABLE_NAME FROM information_schema.tables WHERE table_name=? AND SLEEP(?);;",
37+
"Datastore/statement/MySQL/tables/select",
38+
1,
39+
"??",
40+
"??",
41+
"??",
42+
{
43+
"backtrace": [
44+
" in mysqli_stmt::execute called at __FILE__ (??)",
45+
" in doSQL called at __FILE__ (??)"
46+
]
47+
}
48+
]
49+
]
50+
]
51+
*/
52+
53+
/*EXPECT
54+
If you see this message, it didn't crash
55+
*/
56+
57+
/*EXPECT_TRACED_ERRORS
58+
null
59+
*/
60+
61+
/* Create a mysqli::stmt object using "prepare" but do not execute.
62+
The result will be the mysqli:stmt object will be released when
63+
this function exits and be reused.
64+
*/
65+
function justPrepare($dbConn)
66+
{
67+
$stmt2 = $dbConn->prepare("SELECT ?");
68+
}
69+
70+
/* Run an SQL query.
71+
Params:
72+
$dbConn mysql connection object
73+
$delay delay for query in seconds
74+
$explainable true if query is explainable, otherwise an
75+
unexplainable sql query is run
76+
*/
77+
function doSQL($dbConn, $delay, $explainable) {
78+
79+
/* if sql statement has 2 ';' then agent considers it as multi-statement
80+
and treats it as unexplainable, see nr_php_explain_mysql_query_is_explainable()
81+
*/
82+
if ($explainable) {
83+
$suffix = "";
84+
} else {
85+
$suffix = ";;";
86+
}
87+
88+
$stmt = $dbConn->prepare("SELECT TABLE_NAME FROM information_schema.tables WHERE table_name=? AND SLEEP(?)" . $suffix);
89+
90+
if (! $stmt) {
91+
throw new Exception("Prepare Failed : " . $dbConn->error);
92+
}
93+
94+
$table = "STATISTICS";
95+
$stmt->bind_param('si', $table, $delay);
96+
if (! $stmt->execute()) {
97+
throw new Exception("Execute Failed : " . $stmt->error);
98+
}
99+
100+
$stmt->bind_result($someId);
101+
$stmt->fetch();
102+
$stmt->close();
103+
}
104+
105+
/* main code */
106+
require_once(realpath (dirname ( __FILE__ )) . '/../../include/config.php');
107+
108+
$dbConn = new mysqli($MYSQL_HOST, $MYSQL_USER, $MYSQL_PASSWD, $MYSQL_DB, $MYSQL_PORT, $MYSQL_SOCKET);
109+
110+
/* run a test where a prepared, explainable statement is prepared
111+
but not executed. Then run a prepared, unexplainable slow sql
112+
query which should not be explained. This will lead to the
113+
first stmt object being reused for the second slow sql query.
114+
115+
Tests for reqgression of a bug where the query string
116+
from a previous, explainable SQL query with the same object ID
117+
("handle") would be used in error.
118+
*/
119+
120+
justPrepare($dbConn);
121+
doSQL($dbConn, 1, false);
122+
123+
echo "If you see this message, it didn't crash\n";
124+

‎tests/integration/mysqli/test_explain_reused_id_multiple_002.php

Lines changed: 176 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,176 @@
1+
<?php
2+
/*
3+
* Copyright 2020 New Relic Corporation. All rights reserved.
4+
* SPDX-License-Identifier: Apache-2.0
5+
*/
6+
7+
/*DESCRIPTION
8+
The agent should generate explain plans even when object IDs are reused
9+
and some of the SQL strings are not explainable. This tests that if
10+
a object ID is reused and a new mysqli::stmt object is created with an
11+
unexplainable SQL string that the "mysqli_entries" entry for this
12+
object ID ("handle") has it "query" parameter cleared. This prevents
13+
using an older, stale "query" parameter (from a myqsli::stmt object
14+
which was reclaimed by PHP) being using incorrectly with a newer query.
15+
16+
This test is like "_001" version but an additional, explainable slow SQL
17+
query in run at the end to ensure these are also recorded properly.
18+
*/
19+
20+
/*SKIPIF
21+
<?php
22+
require("skipif.inc");
23+
*/
24+
25+
/*INI
26+
newrelic.transaction_tracer.explain_enabled = true
27+
newrelic.transaction_tracer.explain_threshold = 500
28+
newrelic.transaction_tracer.record_sql = obfuscated
29+
*/
30+
31+
/*EXPECT_SLOW_SQLS
32+
[
33+
[
34+
[
35+
"OtherTransaction/php__FILE__",
36+
"\u003cunknown\u003e",
37+
"??",
38+
"SELECT TABLE_NAME FROM information_schema.tables WHERE table_name=? AND SLEEP(?)",
39+
"Datastore/statement/MySQL/tables/select",
40+
1,
41+
"??",
42+
"??",
43+
"??",
44+
{
45+
"explain_plan": [
46+
[
47+
"id",
48+
"select_type",
49+
"table",
50+
"type",
51+
"possible_keys",
52+
"key",
53+
"key_len",
54+
"ref",
55+
"rows",
56+
"Extra"
57+
],
58+
[
59+
[
60+
1,
61+
"SIMPLE",
62+
"tables",
63+
"ALL",
64+
null,
65+
"TABLE_NAME",
66+
null,
67+
null,
68+
null,
69+
"Using where; Skip_open_table; Scanned 1 database"
70+
]
71+
]
72+
],
73+
"backtrace": [
74+
" in mysqli_stmt::execute called at __FILE__ (??)",
75+
" in doSQL called at __FILE__ (??)"
76+
]
77+
}
78+
],
79+
[
80+
"OtherTransaction/php__FILE__",
81+
"\u003cunknown\u003e",
82+
"??",
83+
"SELECT TABLE_NAME FROM information_schema.tables WHERE table_name=? AND SLEEP(?);;",
84+
"Datastore/statement/MySQL/tables/select",
85+
1,
86+
"??",
87+
"??",
88+
"??",
89+
{
90+
"backtrace": [
91+
" in mysqli_stmt::execute called at __FILE__ (??)",
92+
" in doSQL called at __FILE__ (??)"
93+
]
94+
}
95+
]
96+
]
97+
]
98+
*/
99+
100+
/*EXPECT
101+
If you see this message, it didn't crash
102+
*/
103+
104+
/*EXPECT_TRACED_ERRORS
105+
null
106+
*/
107+
108+
/* Create a mysqli::stmt object using "prepare" but do not execute.
109+
The result will be the mysqli:stmt object will be released when
110+
this function exits and be reused.
111+
*/
112+
function justPrepare($dbConn)
113+
{
114+
$stmt2 = $dbConn->prepare("SELECT ?");
115+
}
116+
117+
/* Run an SQL query.
118+
Params:
119+
$dbConn mysql connection object
120+
$delay delay for query in seconds
121+
$explainable true if query is explainable, otherwise an
122+
unexplainable sql query is run
123+
*/
124+
function doSQL($dbConn, $delay, $explainable) {
125+
126+
/* if sql statement has 2 ';' then agent considers it as multi-statement
127+
and treats it as unexplainable, see nr_php_explain_mysql_query_is_explainable()
128+
*/
129+
if ($explainable) {
130+
$suffix = "";
131+
} else {
132+
$suffix = ";;";
133+
}
134+
135+
$stmt = $dbConn->prepare("SELECT TABLE_NAME FROM information_schema.tables WHERE table_name=? AND SLEEP(?)" . $suffix);
136+
137+
if (! $stmt) {
138+
throw new Exception("Prepare Failed : " . $dbConn->error);
139+
}
140+
141+
$table = "STATISTICS";
142+
$stmt->bind_param('si', $table, $delay);
143+
if (! $stmt->execute()) {
144+
throw new Exception("Execute Failed : " . $stmt->error);
145+
}
146+
147+
$stmt->bind_result($someId);
148+
$stmt->fetch();
149+
$stmt->close();
150+
}
151+
152+
153+
154+
/* main code */
155+
require_once(realpath (dirname ( __FILE__ )) . '/../../include/config.php');
156+
157+
$dbConn = new mysqli($MYSQL_HOST, $MYSQL_USER, $MYSQL_PASSWD, $MYSQL_DB, $MYSQL_PORT, $MYSQL_SOCKET);
158+
159+
/* run a test where a prepared, explainable statement is prepared
160+
but not executed. Then run a prepared, unexplainable slow sql
161+
query which should not be explained. This will lead to the
162+
first stmt object being reused for the second slow sql query.
163+
Then run an explainable, slow SQL query and confirm it is
164+
explained.
165+
166+
Tests for reqgression of a bug where the query string
167+
from a previous, explainable SQL query with the same object ID
168+
("handle") would be used in error.
169+
*/
170+
171+
justPrepare($dbConn);
172+
doSQL($dbConn, 1, false);
173+
doSQL($dbConn, 1, true);
174+
175+
echo "If you see this message, it didn't crash\n";
176+

0 commit comments

Comments
 (0)