Azure PostgreSQL Flexible Server Logs, auto_explain.format escape characters

Question

Hi,

When attempting to read auto_explain plans out of either the Az PostgreSQL server logs (where you can download them) or out of something like LogAnalytics, the explain plan is messed up.

Take for example, something like this. There is no easy way to convert the log snippet after "plan:" to JSON. There are all sorts of escape chars.

This seems to be specific to LogAnalytics and Server Logs. When we have services pulling this in from an event hub, this issue doesn't seem to occur.

Is there anyway to easily convert this back to clean JSON?

2024-07-31 13:47:57.387 UTC [2231] [user=datadog] LOG:  duration: 291.305 ms  plan:\n{\n  \"Query Text\": \"/* service='datadog-agent' */ SELECT datadog.explain_statement($stmt$EXECUTE dd_9679e295b337ad26(null,null)$stmt$)\",\n  \"Plan\": {\n    \"Node Type\": \"ProjectSet\",\n    \"Parallel Aware\": false,\n    \"Async Capable\": false,\n    \"Startup Cost\": 0.00,\n    \"Total Cost\": 5.27,\n    \"Plan Rows\": 1000,\n    \"Plan Width\": 32,\n    \"Actual Startup Time\": 291.198,\n    \"Actual Total Time\": 291.200,\n    \"Actual Rows\": 1,\n    \"Actual Loops\": 1,\n    \"Output\": [\"explain_statement('EXECUTE dd_9679e295b337ad26(null,null)'::text)\"],\n    \"Shared Hit Blocks\": 41202,\n    \"Shared Read Blocks\": 1140,\n    \"Shared Dirtied Blocks\": 0,\n    \"Shared Written Blocks\": 0,\n    \"Local Hit Blocks\": 0,\n    \"Local Read Blocks\": 0,\n    \"Local Dirtied Blocks\": 0,\n    \"Local Written Blocks\": 0,\n    \"Temp Read Blocks\": 0,\n    \"Temp Written Blocks\": 0,\n    \"I/O Read Time\": 188.783,\n    \"I/O Write Time\": 0.000,\n    \"WAL Records\": 0,\n    \"WAL FPI\": 0,\n    \"WAL Bytes\": 0,\n    \"Plans\": [\n      {\n        \"Node Type\": \"Result\",\n        \"Parent Relationship\": \"Outer\",\n        \"Parallel Aware\": false,\n        \"Async Capable\": false,\n        \"Startup Cost\": 0.00,\n        \"Total Cost\": 0.01,\n        \"Plan Rows\": 1,\n        \"Plan Width\": 0,\n        \"Actual Startup Time\": 0.000,\n        \"Actual Total Time\": 0.001,\n        \"Actual Rows\": 1,\n        \"Actual Loops\": 1,\n        \"Shared Hit Blocks\": 0,\n        \"Shared Read Blocks\": 0,\n        \"Shared Dirtied Blocks\": 0,\n        \"Shared Written Blocks\": 0,\n        \"Local Hit Blocks\": 0,\n        \"Local Read Blocks\": 0,\n        \"Local Dirtied Blocks\": 0,\n        \"Local Written Blocks\": 0,\n        \"Temp Read Blocks\": 0,\n        \"Temp Written Blocks\": 0,\n        \"I/O Read Time\": 0.000,\n        \"I/O Write Time\": 0.000,\n        \"WAL Records\": 0,\n        \"WAL FPI\": 0,\n        \"WAL Bytes\": 0\n      }\n    ]\n  },\n  \"Settings\": {\n    \"effective_cache_size\": \"8GB\",\n    \"effective_io_concurrency\": \"200\",\n    \"jit\": \"off\",\n    \"max_parallel_workers\": \"4\",\n    \"plan_cache_mode\": \"force_generic_plan\",\n    \"random_page_cost\": \"1.1\",\n    \"temp_buffers\": \"16MB\",\n    \"work_mem\": \"30MB\"\n  },\n  \"Triggers\": [\n  ]\n}

Answer 1

Hi @ Eric Singer,

Thanks for the question and using MS Q&A platform.

I'm glad that you were able to resolve your issue and thank you for posting your solution so that others experiencing the same thing can easily reference this! Since the Microsoft Q&A community has a policy that "The question author cannot accept their own answer. They can only accept answers by others ", I'll repost your solution in case you'd like to accept the answer.

Ask: When attempting to read auto_explain plans out of either the Az PostgreSQL server logs (where you can download them) or out of something like Log Analytics, the explain plan is messed up.

Take for example, something like this. There is no easy way to convert the log snippet after "plan:" to JSON. There are all sorts of escape chars.

This seems to be specific to Log Analytics and Server Logs. When we have services pulling this in from an event hub, this issue doesn't seem to occur.

Is there any way to easily convert this back to clean JSON?

2024-07-31 13:47:57.387 UTC [2231] [user=datadog] LOG: duration: 291.305 ms plan:\n{\n \"Query Text\": \"/* service='datadog-agent' */ SELECT datadog.explain_statement($stmt$EXECUTE dd_9679e295b337ad26(null,null)$stmt$)\",\n \"Plan\": {\n \"Node Type\": \"ProjectSet\",\n \"Parallel Aware\": false,\n \"Async Capable\": false,\n \"Startup Cost\": 0.00,\n \"Total Cost\": 5.27,\n \"Plan Rows\": 1000,\n \"Plan Width\": 32,\n \"Actual Startup Time\": 291.198,\n \"Actual Total Time\": 291.200,\n \"Actual Rows\": 1,\n \"Actual Loops\": 1,\n \"Output\": [\"explain_statement('EXECUTE dd_9679e295b337ad26(null,null)'::text)\"],\n \"Shared Hit Blocks\": 41202,\n \"Shared Read Blocks\": 1140,\n \"Shared Dirtied Blocks\": 0,\n \"Shared Written Blocks\": 0,\n \"Local Hit Blocks\": 0,\n \"Local Read Blocks\": 0,\n \"Local Dirtied Blocks\": 0,\n \"Local Written Blocks\": 0,\n \"Temp Read Blocks\": 0,\n \"Temp Written Blocks\": 0,\n \"I/O Read Time\": 188.783,\n \"I/O Write Time\": 0.000,\n \"WAL Records\": 0,\n \"WAL FPI\": 0,\n \"WAL Bytes\": 0,\n \"Plans\": [\n {\n \"Node Type\": \"Result\",\n \"Parent Relationship\": \"Outer\",\n \"Parallel Aware\": false,\n \"Async Capable\": false,\n \"Startup Cost\": 0.00,\n \"Total Cost\": 0.01,\n \"Plan Rows\": 1,\n \"Plan Width\": 0,\n \"Actual Startup Time\": 0.000,\n \"Actual Total Time\": 0.001,\n \"Actual Rows\": 1,\n \"Actual Loops\": 1,\n \"Shared Hit Blocks\": 0,\n \"Shared Read Blocks\": 0,\n \"Shared Dirtied Blocks\": 0,\n \"Shared Written Blocks\": 0,\n \"Local Hit Blocks\": 0,\n \"Local Read Blocks\": 0,\n \"Local Dirtied Blocks\": 0,\n \"Local Written Blocks\": 0,\n \"Temp Read Blocks\": 0,\n \"Temp Written Blocks\": 0,\n \"I/O Read Time\": 0.000,\n \"I/O Write Time\": 0.000,\n \"WAL Records\": 0,\n \"WAL FPI\": 0,\n \"WAL Bytes\": 0\n }\n ]\n },\n \"Settings\": {\n \"effective_cache_size\": \"8GB\",\n \"effective_io_concurrency\": \"200\",\n \"jit\": \"off\",\n \"max_parallel_workers\": \"4\",\n \"plan_cache_mode\": \"force_generic_plan\",\n \"random_page_cost\": \"1.1\",\n \"temp_buffers\": \"16MB\",\n \"work_mem\": \"30MB\"\n },\n \"Triggers\": [\n ]\n}

Solution: I found that if i wrap the "plan:" and the remaining part of the message in a fully qualified JSON string it helps with deserialzing it.

For example

Open the with { "Message": "Plan...... FULL MESSAGE ...." }

Then i can deserialize it. So it really seems like the JSON string simply isn't fully qualified.

If I missed anything please let me know and I'd be happy to add it to my answer, or feel free to comment below with any additional information.

If you have any other questions, please let me know. Thank you again for your time and patience throughout this issue.

---

Please don’t forget to Accept Answer and Yes for "was this answer helpful" wherever the information provided helps you, this can be beneficial to other community members.

Answer 2

I found that if i wrap the "plan:" and the remaining part of the message in a fully qualified JSON string it helps with deserialzing it.

For example

Open the with { "Message": "Plan...... FULL MESSAGE ...." }

Then i can deserialize it. So it really seems like the JSON string simply isn't fully qualified.