Query string truncation/off by one error when explaining some queries?

[terrorobe]

I've noticed these errors in a production environment which seem rather odd given the fact that the user doesn't handle/change the query string anywhere.

So far I haven't been able to reproduce it by hand, will give more input as soon as I've got more.

planid              | 238997
userid              | 16403
dbid                | 25450
query               | SELECT "places".* FROM "places"  WHERE (earth_box(ll_to_earth(46.5845336914063, 14.7958154678345), 300) @> ll_to_earth(coordinate[0], coordinate[1])) AND ((places.category_id IS NULL OR places.category_id != 15))
had_our_search_path | t
from_our_database   | t


atlas=# select pg_stat_plans_explain(238997,16403, 25450);
ERROR:  syntax error at end of input
LINE 1: ...ND ((places.category_id IS NULL OR places.category_id != 15)
                                                                      ^
QUERY:  EXPLAIN SELECT "places".* FROM "places"  WHERE (earth_box(ll_to_earth(46.5845336914063, 14.7958154678345), 300) @> ll_to_earth(coordinate[0], coordinate[1])) AND ((places.category_id IS NULL OR places.category_id != 15)

[petergeoghegan]

That's strange. I haven't been able to reproduce this. It could be a 9.1 specific issue.

[simonat2ndQuadrant]

On 29 January 2013 22:27, Peter Geoghegan [email protected] wrote:

That's strange. I haven't been able to reproduce this. It could be a 9.1 specific issue.

Looks like an off-by-one error at the end of the string.

Simon Riggs http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services

[MSch]

We're also suffering from this. Any ideas for a workaround?

[petergeoghegan]

What version of Postgres are you using, Msch?

[petergeoghegan]

@terrorobe @MSch Did either of you see this again? I can't help but suspect that it might have had something to do with the fact that this query contains SQL functions, which were recently shown to be a problematic case for pg_stat_plans due to planner pre-processing invoking the executor multiple times for the same client supplied query - all at the same "level". But I've never been able to recreate the problem, and I still can't figure it out in light of what we now know about that case.

What I think this might be down to is the fact that pg_stat_plans_explain() doesn't do an encoding conversion, which it really should. However, the fact that the hash key includes the encoding id is really just a notational convenience. As both pg_stat_plans and pg_stat_statements say:

• Presently, the query encoding is fully determined by the source database
• and so we don't really need it to be in the key. But that might not always
• be true. Anyway it's notationally convenient to pass it as part of the key.

I cannot think of a scenario in which this should matter - the sourceText that we get from the core system should always be of the encoding returned by GetDatabaseEncoding(), so pg_stat_statements (and by extension pg_stat_plans) isn't really obligated to care about encoding at all. And even if it did matter, I'm having a hard time imaging why we wouldn't get away with it in this case.

However, despite all this, I will draft a patch to make pg_stat_plans do an encoding conversion when generating an EXPLAIN string. It makes sense from a maintainability perspective - as long as pg_stat_plans() (the function) is doing this, there ought to be parity within pg_stat_plans_explain().

[terrorobe]

I just checked our database.

For ~3.6 million collected plan snapshots we've got about 350.000 which caused errors.

pgaweb=# select count(*) as cnt, regexp_replace(substring(explain_error from '^(.*?)\n'), '\d+', '___', 'g') as explainerror from plan_snapshots where explain_error is not null group by explainerror order by cnt desc;
  cnt   |                                                                                                                              explainerror                                                                                                                              
--------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 244184 | NOTICE:  Cannot explain prepared query (planid: ___)
  82062 | ERROR:  syntax error at or near "BEGIN"
  19788 | NOTICE:  Cannot explain truncated query string (planid: ___)
   2138 | ERROR:  relation "delcandidates" does not exist
   1701 | ERROR:  relation "batch" does not exist
   1573 | ERROR:  relation "btemp___" does not exist
   1044 | WARNING:  Existing pg_stat_plans entry planid (___) differs from new plan for query (___).
    445 | ERROR:  relation "cpy_tmp" does not exist
    115 | ERROR:  planid '___' does not exist in shared hashtable.
     30 | ERROR:  relation "temp" does not exist
     27 | ERROR:  there is no parameter $___
     21 | NOTICE:  text-search query doesn't contain lexemes: ""
     17 | ERROR:  relation "<redacted>" does not exist
     10 | NOTICE:  text-search query contains only stop words or doesn't contain lexemes, ignored
     10 | ERROR:  relation "temp___" does not exist
      8 | psql: FATAL:  sorry, too many clients already
      5 | ERROR:  relation "email_campaign_abtest" does not exist
      4 | ERROR:  relation "rollback_test" does not exist
      4 | ERROR:  relation "payment_stats" does not exist
      3 | ERROR:  relation "first_payments" does not exist
      3 | ERROR:  current search_path does not match that for original execution of query originally produced planid ___. Furthermore, plans for both queries differ(The new planid is ___), very probably due to each plan referencing what are technically distinct relations.
      2 | ERROR:  relation "<redacted>" does not exist
      2 | ERROR:  relation "email_campaigns" does not exist
      2 | ERROR:  syntax error at or near "OR"
      2 | ERROR:  relation "<redacted>" does not exist
      1 | ERROR:  relation "public.routes_routepoints" does not exist
      1 | ERROR:  relation "public.scheduled_jobs" does not exist
      1 | ERROR:  syntax error at end of input
      1 | ERROR:  column fk.alias_page_id does not exist
      1 | ERROR:  column fiber_page.relative_url does not exist
(30 rows)

The one query that caused the "syntax error at end of input" is a query which looks like if it got truncated at plans_query_size:

pgaweb=# select query, explain_error, length(query) from plan_snapshots where explain_error like 'ERROR:  syntax error at end of input%';
-[ RECORD 1 ]-+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
query         | SELECT "queries".* FROM "queries"  WHERE "queries"."database_id" = 17 AND "queries"."id" IN (1789, 3377, 1472, 1510, 1103, 4121, 7942, 2278, 1485, 1477, 3996, 1055, 1544, 1480, 1471, 6286, 1066, 9715, 9716, 1490, 1483, 1494, 4124, 1091, 3416, 3422, 1081, 9717, 2178, 1754, 1506, 9718, 7946, 7947, 1479, 1755, 1522, 1484, 6294, 1539, 3995, 1476, 9719, 1503, 9720, 9721, 7755, 1533, 1474, 1475, 6355, 1504, 1537, 6321, 1063, 1065, 1486, 9722, 3625, 1070, 6461, 9723, 1523, 1752, 2179, 1090, 7758, 1491, 9724, 1547, 1056, 3561, 1748, 1068, 7757, 1505, 4128, 7062, 1756, 1481, 3397, 7754, 9725, 1507, 1541, 3599, 9726, 2070, 1478, 1082, 1509, 3671, 1059, 6830, 4269, 2075, 1482, 3988, 3989, 1495, 4111, 6414, 2068, 2067, 3438, 1057, 2076, 4167, 3812, 3811, 6302, 7756, 4271, 9735, 7948, 3628, 3553, 4108, 3810, 4130, 3540, 2077, 9736, 3879, 3350, 7759, 9739, 3371, 3593, 3890, 6873, 6326, 3895, 9740, 3372, 3408, 3903, 6574, 3901, 3885, 7861, 3443, 6458, 7863, 3473, 3474, 9741, 3562, 3882, 1061, 3492, 6575, 6942, 3902, 4125, 2279, 3483, 3881, 3552, 3886, 3896, 3584, 3893, 4236, 4133, 3904, 4134, 3911, 6874, 3615, 9743, 4155, 4156, 7627, 6329, 7763, 4154, 7175, 9744, 4182, 4132, 7628, 9752, 9753, 9754, 8291, 6454, 4139, 6666, 6667, 4221, 3529, 6981, 2062, 4141, 4189, 7854, 9756, 9757, 4178, 9758, 7999, 7951, 9759, 9760, 4162, 6344, 4227, 6285, 3990, 6295, 4228, 6831, 6342, 9765, 3897, 6310, 6336, 6891, 6316, 4160, 4255, 1496, 4161, 6577, 6383, 9770, 6417, 4238, 6308, 3670, 6652, 4158, 3669, 4223, 3898, 9773, 9774, 4157, 4226, 6338, 3984, 6284, 3905, 9777, 9778, 9779, 6882, 6880, 9780, 9781, 3683, 9784, 9785, 3987, 6435, 1508, 3900, 6777, 7515, 7403, 6312, 3951, 4201, 9795, 7413, 7847, 6418, 6571, 6419, 9799, 4217, 9801, 4218, 6865, 6318, 9802, 7152, 6636, 7253, 6555, 7255, 6579, 9803, 6540, 6305, 6371, 7184, 8350, 7114, 3684, 6675, 9804, 6388, 9805, 6558, 6685, 6932, 3975, 4136, 4232, 4137, 7377, 6385, 4172, 9808, 6735, 6584, 6828, 6592, 9809, 4143, 6287, 7456, 6289, 6426, 9811, 7508, 4187, 4197, 6313, 4200, 9821, 6317, 2220, 4114
explain_error | ERROR:  syntax error at end of input
              | LINE 1: ..., 9811, 7508, 4187, 4197, 6313, 4200, 9821, 6317, 2220, 4114
              |                                                                        ^
              | QUERY:  EXPLAIN SELECT "queries".* FROM "queries"  WHERE "queries"."database_id" = 17 AND "queries"."id" IN (1789, 3377, 1472, 1510, 1103, 4121, 7942, 2278, 1485, 1477, 3996, 1055, 1544, 1480, 1471, 6286, 1066, 9715, 9716, 1490, 1483, 1494, 4124, 1091, 3416, 3422, 1081, 9717, 2178, 1754, 1506, 9718, 7946, 7947, 1479, 1755, 1522, 1484, 6294, 1539, 3995, 1476, 9719, 1503, 9720, 9721, 7755, 1533, 1474, 1475, 6355, 1504, 1537, 6321, 1063, 1065, 1486, 9722, 3625, 1070, 6461, 9723, 1523, 1752, 2179, 1090, 7758, 1491, 9724, 1547, 1056, 3561, 1748, 1068, 7757, 1505, 4128, 7062, 1756, 1481, 3397, 7754, 9725, 1507, 1541, 3599, 9726, 2070, 1478, 1082, 1509, 3671, 1059, 6830, 4269, 2075, 1482, 3988, 3989, 1495, 4111, 6414, 2068, 2067, 3438, 1057, 2076, 4167, 3812, 3811, 6302, 7756, 4271, 9735, 7948, 3628, 3553, 4108, 3810, 4130, 3540, 2077, 9736, 3879, 3350, 7759, 9739, 3371, 3593, 3890, 6873, 6326, 3895, 9740, 3372, 3408, 3903, 6574, 3901, 3885, 7861, 3443, 6458, 7863, 3473, 3474, 9741, 3562, 3882, 1061, 3492, 6575, 6942, 3902, 4125, 2279, 3483, 3881, 3552, 3886, 3896, 3584, 3893, 4236, 4133, 3904, 4134, 3911, 6874, 3615, 9743, 4155, 4156, 7627, 6329, 7763, 4154, 7175, 9744, 4182, 4132, 7628, 9752, 9753, 9754, 8291, 6454, 4139, 6666, 6667, 4221, 3529, 6981, 2062, 4141, 4189, 7854, 9756, 9757, 4178, 9758, 7999, 7951, 9759, 9760, 4162, 6344, 4227, 6285, 3990, 6295, 4228, 6831, 6342, 9765, 3897, 6310, 6336, 6891, 6316, 4160, 4255, 1496, 4161, 6577, 6383, 9770, 6417, 4238, 6308, 3670, 6652, 4158, 3669, 4223, 3898, 9773, 9774, 4157, 4226, 6338, 3984, 6284, 3905, 9777, 9778, 9779, 6882, 6880, 9780, 9781, 3683, 9784, 9785, 3987, 6435, 1508, 3900, 6777, 7515, 7403, 6312, 3951, 4201, 9795, 7413, 7847, 6418, 6571, 6419, 9799, 4217, 9801, 4218, 6865, 6318, 9802, 7152, 6636, 7253, 6555, 7255, 6579, 9803, 6540, 6305, 6371, 7184, 8350, 7114, 3684, 6675, 9804, 6388, 9805, 6558, 6685, 6932, 3975, 4136, 4232, 4137, 7377, 6385, 4172, 9808, 6735, 6584, 6828, 6592, 9809, 4143, 6287, 7456, 6289, 6426, 9811, 7508, 4187, 4197, 6313, 4200, 9821, 6317, 2220, 4114
              | 
length        | 2047

pgaweb=# 

The original database using the earthbox queries isn't in there anymore so I guess that was probably the culprit after all.

I'd say we close this bug for now - if it should resurface I'll reopen it again.