{"id":12120,"date":"2018-11-30T18:41:57","date_gmt":"2018-11-30T17:41:57","guid":{"rendered":"https:\/\/www.dbi-services.com\/blog\/postgresql-12-log_statement_sample_rate\/"},"modified":"2018-11-30T18:41:57","modified_gmt":"2018-11-30T17:41:57","slug":"postgresql-12-log_statement_sample_rate","status":"publish","type":"post","link":"https:\/\/www.dbi-services.com\/blog\/postgresql-12-log_statement_sample_rate\/","title":{"rendered":"PostgreSQL 12: log_statement_sample_rate"},"content":{"rendered":"<p>A common way to identify long running queries in PostgreSQL is to set <a href=\"https:\/\/www.postgresql.org\/docs\/current\/runtime-config-logging.html\" target=\"_blank\" rel=\"noopener noreferrer\">log_min_duration_statement<\/a> to a value that is known to cause troubles. In other words: If you know most of your statements usually execute in under a second you could set log_min_duration_statement to &#8220;2s&#8221; (which means two seconds) so that whenever a statement takes longer than two seconds it will be reported in the log file. The issue with this however is, that this can cause a lot of activity in the server log file which of course is not good for performance as well. PostgreSQL 12 will probably come with a solution to that.<\/p>\n<p><!--more--><\/p>\n<p>The default value of log_min_duration_statement is &#8220;-1&#8221;, which means disabled:<\/p>\n<pre class=\"brush: sql; gutter: true; first-line: 1\">\npostgres=# select version();\n                                                  version                                                   \n------------------------------------------------------------------------------------------------------------\n PostgreSQL 12devel on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-28), 64-bit\n(1 row)\n\npostgres=# show log_min_duration_statement;\n log_min_duration_statement \n----------------------------\n -1\n(1 row)\n<\/pre>\n<p>Lets set this to 5ms and then generate some queries:<\/p>\n<pre class=\"brush: sql; gutter: true; first-line: 1\">\npostgres=# alter system set log_min_duration_statement = '5ms';\nALTER SYSTEM\npostgres=# select pg_reload_conf();\n pg_reload_conf \n----------------\n t\n(1 row)\n\npostgres=# show log_min_duration_statement;\n log_min_duration_statement \n----------------------------\n 5ms\n(1 row)\n<\/pre>\n<p>When we execute some queries that take longer than 5ms they should get reported in the log file:<\/p>\n<pre class=\"brush: sql; gutter: true; first-line: 1\">\npostgres=# select 'select pg_sleep(0.5)' from generate_series(1,10); gexec\n       ?column?       \n----------------------\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n(10 rows)\n\n pg_sleep \n----------\n \n(1 row)\n\n...\n<\/pre>\n<p>Looking at the log file there are exactly 10 entries:<\/p>\n<pre class=\"brush: sql; gutter: true; first-line: 1\">\n2018-11-28 03:13:32.240 CET - 20 - 28978 - [local] - postgres@postgres LOG:  duration: 529.825 ms  statement: select pg_sleep(0.5)\n2018-11-28 03:13:32.770 CET - 21 - 28978 - [local] - postgres@postgres LOG:  duration: 529.904 ms  statement: select pg_sleep(0.5)\n2018-11-28 03:13:33.273 CET - 22 - 28978 - [local] - postgres@postgres LOG:  duration: 501.729 ms  statement: select pg_sleep(0.5)\n2018-11-28 03:13:33.783 CET - 23 - 28978 - [local] - postgres@postgres LOG:  duration: 509.532 ms  statement: select pg_sleep(0.5)\n2018-11-28 03:13:34.305 CET - 24 - 28978 - [local] - postgres@postgres LOG:  duration: 520.946 ms  statement: select pg_sleep(0.5)\n2018-11-28 03:13:34.809 CET - 25 - 28978 - [local] - postgres@postgres LOG:  duration: 502.624 ms  statement: select pg_sleep(0.5)\n2018-11-28 03:13:35.315 CET - 26 - 28978 - [local] - postgres@postgres LOG:  duration: 505.043 ms  statement: select pg_sleep(0.5)\n2018-11-28 03:13:35.817 CET - 27 - 28978 - [local] - postgres@postgres LOG:  duration: 502.034 ms  statement: select pg_sleep(0.5)\n2018-11-28 03:13:36.321 CET - 28 - 28978 - [local] - postgres@postgres LOG:  duration: 503.417 ms  statement: select pg_sleep(0.5)\n2018-11-28 03:13:36.824 CET - 29 - 28978 - [local] - postgres@postgres LOG:  duration: 501.790 ms  statement: select pg_sleep(0.5)\n<\/pre>\n<p>Imagine there are thousands of statements that exceed log_min_duration_statement: This will make the log file grow quite fast and performance will suffer because writing the log file takes resources as well. PostgreSQL 12 introduces a new parameter &#8220;log_statement_sample_rate&#8221; which helps with this:<\/p>\n<pre class=\"brush: sql; gutter: true; first-line: 1\">\npostgres=# show log_statement_sample_rate;\n log_statement_sample_rate \n---------------------------\n 1\n(1 row)\n<\/pre>\n<p>The default is 1 which means log all statements that exceed the log_min_duration_statement threshold. When that is too much we can now go and say: We want only 10% of these statements getting logged:<\/p>\n<pre class=\"brush: sql; gutter: true; first-line: 1\">\npostgres=# alter system set log_statement_sample_rate=0.1;\nALTER SYSTEM\npostgres=# select pg_reload_conf();\n pg_reload_conf \n----------------\n t\n(1 row)\n\npostgres=# show log_statement_sample_rate;\n log_statement_sample_rate \n---------------------------\n 0.1\n(1 row)\n<\/pre>\n<p>Doing the same test as above again:<\/p>\n<pre class=\"brush: sql; gutter: true; first-line: 1\">\npostgres=# select 'select pg_sleep(0.5)' from generate_series(1,10); gexec\n       ?column?       \n----------------------\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n select pg_sleep(0.5)\n(10 rows)\n\n pg_sleep \n----------\n \n(1 row)\n\n...\n<\/pre>\n<p>&#8230; we only get one entry in the log file, instead of 10:<\/p>\n<pre class=\"brush: sql; gutter: true; first-line: 1\">\n2018-11-28 03:20:36.218 CET - 34 - 28978 - [local] - postgres@postgres LOG:  duration: 504.845 ms  statement: select pg_sleep(0.5)\n<\/pre>\n<p>Nice. Btw: The commit is <a href=\"https:\/\/git.postgresql.org\/gitweb\/?p=postgresql.git;a=commit;h=88bdbd3f746049834ae3cc972e6e650586ec3c9d\" target=\"_blank\" rel=\"noopener noreferrer\">here<\/a>.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>A common way to identify long running queries in PostgreSQL is to set log_min_duration_statement to a value that is known to cause troubles. In other words: If you know most of your statements usually execute in under a second you could set log_min_duration_statement to &#8220;2s&#8221; (which means two seconds) so that whenever a statement takes [&hellip;]<\/p>\n","protected":false},"author":28,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[229],"tags":[77],"type_dbi":[],"class_list":["post-12120","post","type-post","status-publish","format-standard","hentry","category-database-administration-monitoring","tag-postgresql"],"acf":[],"yoast_head":"<!-- This site is optimized with the Yoast SEO Premium plugin v28.8 (Yoast SEO v28.8) - https:\/\/yoast.com\/product\/yoast-seo-premium-wordpress\/ -->\n<title>PostgreSQL 12: log_statement_sample_rate - dbi Blog<\/title>\n<meta name=\"robots\" content=\"index, follow, max-snippet:-1, max-image-preview:large, max-video-preview:-1\" \/>\n<link rel=\"canonical\" href=\"https:\/\/www.dbi-services.com\/blog\/postgresql-12-log_statement_sample_rate\/\" \/>\n<meta property=\"og:locale\" content=\"en_US\" \/>\n<meta property=\"og:type\" content=\"article\" \/>\n<meta property=\"og:title\" content=\"PostgreSQL 12: log_statement_sample_rate\" \/>\n<meta property=\"og:description\" content=\"A common way to identify long running queries in PostgreSQL is to set log_min_duration_statement to a value that is known to cause troubles. In other words: If you know most of your statements usually execute in under a second you could set log_min_duration_statement to &#8220;2s&#8221; (which means two seconds) so that whenever a statement takes [&hellip;]\" \/>\n<meta property=\"og:url\" content=\"https:\/\/www.dbi-services.com\/blog\/postgresql-12-log_statement_sample_rate\/\" \/>\n<meta property=\"og:site_name\" content=\"dbi Blog\" \/>\n<meta property=\"article:published_time\" content=\"2018-11-30T17:41:57+00:00\" \/>\n<meta name=\"author\" content=\"Open source Team\" \/>\n<meta name=\"twitter:card\" content=\"summary_large_image\" \/>\n<meta name=\"twitter:label1\" content=\"Written by\" \/>\n\t<meta name=\"twitter:data1\" content=\"Open source Team\" \/>\n\t<meta name=\"twitter:label2\" content=\"Est. reading time\" \/>\n\t<meta name=\"twitter:data2\" content=\"3 minutes\" \/>\n<script type=\"application\/ld+json\" class=\"yoast-schema-graph\">{\"@context\":\"https:\\\/\\\/schema.org\",\"@graph\":[{\"@type\":\"Article\",\"@id\":\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/postgresql-12-log_statement_sample_rate\\\/#article\",\"isPartOf\":{\"@id\":\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/postgresql-12-log_statement_sample_rate\\\/\"},\"author\":{\"name\":\"Open source Team\",\"@id\":\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/#\\\/schema\\\/person\\\/4bae5e5dd8c7d48edbd948772b49b202\"},\"headline\":\"PostgreSQL 12: log_statement_sample_rate\",\"datePublished\":\"2018-11-30T17:41:57+00:00\",\"mainEntityOfPage\":{\"@id\":\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/postgresql-12-log_statement_sample_rate\\\/\"},\"wordCount\":272,\"commentCount\":0,\"keywords\":[\"PostgreSQL\"],\"articleSection\":[\"Database Administration &amp; Monitoring\"],\"inLanguage\":\"en-US\",\"potentialAction\":[{\"@type\":\"CommentAction\",\"name\":\"Comment\",\"target\":[\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/postgresql-12-log_statement_sample_rate\\\/#respond\"]}]},{\"@type\":\"WebPage\",\"@id\":\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/postgresql-12-log_statement_sample_rate\\\/\",\"url\":\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/postgresql-12-log_statement_sample_rate\\\/\",\"name\":\"PostgreSQL 12: log_statement_sample_rate - dbi Blog\",\"isPartOf\":{\"@id\":\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/#website\"},\"datePublished\":\"2018-11-30T17:41:57+00:00\",\"author\":{\"@id\":\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/#\\\/schema\\\/person\\\/4bae5e5dd8c7d48edbd948772b49b202\"},\"breadcrumb\":{\"@id\":\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/postgresql-12-log_statement_sample_rate\\\/#breadcrumb\"},\"inLanguage\":\"en-US\",\"potentialAction\":[{\"@type\":\"ReadAction\",\"target\":[\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/postgresql-12-log_statement_sample_rate\\\/\"]}]},{\"@type\":\"BreadcrumbList\",\"@id\":\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/postgresql-12-log_statement_sample_rate\\\/#breadcrumb\",\"itemListElement\":[{\"@type\":\"ListItem\",\"position\":1,\"name\":\"Accueil\",\"item\":\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/\"},{\"@type\":\"ListItem\",\"position\":2,\"name\":\"PostgreSQL 12: log_statement_sample_rate\"}]},{\"@type\":\"WebSite\",\"@id\":\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/#website\",\"url\":\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/\",\"name\":\"dbi Blog\",\"description\":\"\",\"potentialAction\":[{\"@type\":\"SearchAction\",\"target\":{\"@type\":\"EntryPoint\",\"urlTemplate\":\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/?s={search_term_string}\"},\"query-input\":{\"@type\":\"PropertyValueSpecification\",\"valueRequired\":true,\"valueName\":\"search_term_string\"}}],\"inLanguage\":\"en-US\"},{\"@type\":\"Person\",\"@id\":\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/#\\\/schema\\\/person\\\/4bae5e5dd8c7d48edbd948772b49b202\",\"name\":\"Open source Team\",\"image\":{\"@type\":\"ImageObject\",\"inLanguage\":\"en-US\",\"@id\":\"https:\\\/\\\/secure.gravatar.com\\\/avatar\\\/eb4fb12e386e8c41fdef0733e8114594cf2653e4f55e9fa2161442b8eaf3f657?s=96&d=mm&r=g\",\"url\":\"https:\\\/\\\/secure.gravatar.com\\\/avatar\\\/eb4fb12e386e8c41fdef0733e8114594cf2653e4f55e9fa2161442b8eaf3f657?s=96&d=mm&r=g\",\"contentUrl\":\"https:\\\/\\\/secure.gravatar.com\\\/avatar\\\/eb4fb12e386e8c41fdef0733e8114594cf2653e4f55e9fa2161442b8eaf3f657?s=96&d=mm&r=g\",\"caption\":\"Open source Team\"},\"url\":\"https:\\\/\\\/www.dbi-services.com\\\/blog\\\/author\\\/open-source-team\\\/\"}]}<\/script>\n<!-- \/ Yoast SEO Premium plugin. -->","yoast_head_json":{"title":"PostgreSQL 12: log_statement_sample_rate - dbi Blog","robots":{"index":"index","follow":"follow","max-snippet":"max-snippet:-1","max-image-preview":"max-image-preview:large","max-video-preview":"max-video-preview:-1"},"canonical":"https:\/\/www.dbi-services.com\/blog\/postgresql-12-log_statement_sample_rate\/","og_locale":"en_US","og_type":"article","og_title":"PostgreSQL 12: log_statement_sample_rate","og_description":"A common way to identify long running queries in PostgreSQL is to set log_min_duration_statement to a value that is known to cause troubles. In other words: If you know most of your statements usually execute in under a second you could set log_min_duration_statement to &#8220;2s&#8221; (which means two seconds) so that whenever a statement takes [&hellip;]","og_url":"https:\/\/www.dbi-services.com\/blog\/postgresql-12-log_statement_sample_rate\/","og_site_name":"dbi Blog","article_published_time":"2018-11-30T17:41:57+00:00","author":"Open source Team","twitter_card":"summary_large_image","twitter_misc":{"Written by":"Open source Team","Est. reading time":"3 minutes"},"schema":{"@context":"https:\/\/schema.org","@graph":[{"@type":"Article","@id":"https:\/\/www.dbi-services.com\/blog\/postgresql-12-log_statement_sample_rate\/#article","isPartOf":{"@id":"https:\/\/www.dbi-services.com\/blog\/postgresql-12-log_statement_sample_rate\/"},"author":{"name":"Open source Team","@id":"https:\/\/www.dbi-services.com\/blog\/#\/schema\/person\/4bae5e5dd8c7d48edbd948772b49b202"},"headline":"PostgreSQL 12: log_statement_sample_rate","datePublished":"2018-11-30T17:41:57+00:00","mainEntityOfPage":{"@id":"https:\/\/www.dbi-services.com\/blog\/postgresql-12-log_statement_sample_rate\/"},"wordCount":272,"commentCount":0,"keywords":["PostgreSQL"],"articleSection":["Database Administration &amp; Monitoring"],"inLanguage":"en-US","potentialAction":[{"@type":"CommentAction","name":"Comment","target":["https:\/\/www.dbi-services.com\/blog\/postgresql-12-log_statement_sample_rate\/#respond"]}]},{"@type":"WebPage","@id":"https:\/\/www.dbi-services.com\/blog\/postgresql-12-log_statement_sample_rate\/","url":"https:\/\/www.dbi-services.com\/blog\/postgresql-12-log_statement_sample_rate\/","name":"PostgreSQL 12: log_statement_sample_rate - dbi Blog","isPartOf":{"@id":"https:\/\/www.dbi-services.com\/blog\/#website"},"datePublished":"2018-11-30T17:41:57+00:00","author":{"@id":"https:\/\/www.dbi-services.com\/blog\/#\/schema\/person\/4bae5e5dd8c7d48edbd948772b49b202"},"breadcrumb":{"@id":"https:\/\/www.dbi-services.com\/blog\/postgresql-12-log_statement_sample_rate\/#breadcrumb"},"inLanguage":"en-US","potentialAction":[{"@type":"ReadAction","target":["https:\/\/www.dbi-services.com\/blog\/postgresql-12-log_statement_sample_rate\/"]}]},{"@type":"BreadcrumbList","@id":"https:\/\/www.dbi-services.com\/blog\/postgresql-12-log_statement_sample_rate\/#breadcrumb","itemListElement":[{"@type":"ListItem","position":1,"name":"Accueil","item":"https:\/\/www.dbi-services.com\/blog\/"},{"@type":"ListItem","position":2,"name":"PostgreSQL 12: log_statement_sample_rate"}]},{"@type":"WebSite","@id":"https:\/\/www.dbi-services.com\/blog\/#website","url":"https:\/\/www.dbi-services.com\/blog\/","name":"dbi Blog","description":"","potentialAction":[{"@type":"SearchAction","target":{"@type":"EntryPoint","urlTemplate":"https:\/\/www.dbi-services.com\/blog\/?s={search_term_string}"},"query-input":{"@type":"PropertyValueSpecification","valueRequired":true,"valueName":"search_term_string"}}],"inLanguage":"en-US"},{"@type":"Person","@id":"https:\/\/www.dbi-services.com\/blog\/#\/schema\/person\/4bae5e5dd8c7d48edbd948772b49b202","name":"Open source Team","image":{"@type":"ImageObject","inLanguage":"en-US","@id":"https:\/\/secure.gravatar.com\/avatar\/eb4fb12e386e8c41fdef0733e8114594cf2653e4f55e9fa2161442b8eaf3f657?s=96&d=mm&r=g","url":"https:\/\/secure.gravatar.com\/avatar\/eb4fb12e386e8c41fdef0733e8114594cf2653e4f55e9fa2161442b8eaf3f657?s=96&d=mm&r=g","contentUrl":"https:\/\/secure.gravatar.com\/avatar\/eb4fb12e386e8c41fdef0733e8114594cf2653e4f55e9fa2161442b8eaf3f657?s=96&d=mm&r=g","caption":"Open source Team"},"url":"https:\/\/www.dbi-services.com\/blog\/author\/open-source-team\/"}]}},"_links":{"self":[{"href":"https:\/\/www.dbi-services.com\/blog\/wp-json\/wp\/v2\/posts\/12120","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/www.dbi-services.com\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.dbi-services.com\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.dbi-services.com\/blog\/wp-json\/wp\/v2\/users\/28"}],"replies":[{"embeddable":true,"href":"https:\/\/www.dbi-services.com\/blog\/wp-json\/wp\/v2\/comments?post=12120"}],"version-history":[{"count":0,"href":"https:\/\/www.dbi-services.com\/blog\/wp-json\/wp\/v2\/posts\/12120\/revisions"}],"wp:attachment":[{"href":"https:\/\/www.dbi-services.com\/blog\/wp-json\/wp\/v2\/media?parent=12120"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.dbi-services.com\/blog\/wp-json\/wp\/v2\/categories?post=12120"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.dbi-services.com\/blog\/wp-json\/wp\/v2\/tags?post=12120"},{"taxonomy":"type","embeddable":true,"href":"https:\/\/www.dbi-services.com\/blog\/wp-json\/wp\/v2\/type_dbi?post=12120"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}