{"action":"closed","issue":{"url":"https://api.github.com/repos/DataDog/dd-agent/issues/1312","labels_url":"https://api.github.com/repos/DataDog/dd-agent/issues/1312/labels{/name}","comments_url":"https://api.github.com/repos/DataDog/dd-agent/issues/1312/comments","events_url":"https://api.github.com/repos/DataDog/dd-agent/issues/1312/events","html_url":"https://github.com/DataDog/dd-agent/issues/1312","id":55378450,"number":1312,"title":"[postgres] replication_delay metric doesn't always report accurate details","user":{"login":"miketheman","id":529516,"avatar_url":"https://avatars.githubusercontent.com/u/529516?v=3","gravatar_id":"","url":"https://api.github.com/users/miketheman","html_url":"https://github.com/miketheman","followers_url":"https://api.github.com/users/miketheman/followers","following_url":"https://api.github.com/users/miketheman/following{/other_user}","gists_url":"https://api.github.com/users/miketheman/gists{/gist_id}","starred_url":"https://api.github.com/users/miketheman/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/miketheman/subscriptions","organizations_url":"https://api.github.com/users/miketheman/orgs","repos_url":"https://api.github.com/users/miketheman/repos","events_url":"https://api.github.com/users/miketheman/events{/privacy}","received_events_url":"https://api.github.com/users/miketheman/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/DataDog/dd-agent/labels/checks","name":"checks","color":"444444"}],"state":"closed","locked":false,"assignee":null,"milestone":{"url":"https://api.github.com/repos/DataDog/dd-agent/milestones/43","html_url":"https://github.com/DataDog/dd-agent/milestones/5.4.0","labels_url":"https://api.github.com/repos/DataDog/dd-agent/milestones/43/labels","id":996033,"number":43,"title":"5.4.0","description":null,"creator":{"login":"remh","id":1311477,"avatar_url":"https://avatars.githubusercontent.com/u/1311477?v=3","gravatar_id":"","url":"https://api.github.com/users/remh","html_url":"https://github.com/remh","followers_url":"https://api.github.com/users/remh/followers","following_url":"https://api.github.com/users/remh/following{/other_user}","gists_url":"https://api.github.com/users/remh/gists{/gist_id}","starred_url":"https://api.github.com/users/remh/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/remh/subscriptions","organizations_url":"https://api.github.com/users/remh/orgs","repos_url":"https://api.github.com/users/remh/repos","events_url":"https://api.github.com/users/remh/events{/privacy}","received_events_url":"https://api.github.com/users/remh/received_events","type":"User","site_admin":false},"open_issues":19,"closed_issues":2,"state":"open","created_at":"2015-02-25T23:32:42Z","updated_at":"2015-03-18T21:39:54Z","due_on":null,"closed_at":null},"comments":2,"created_at":"2015-01-24T17:34:14Z","updated_at":"2015-03-18T21:39:54Z","closed_at":"2015-03-18T21:39:54Z","body":"In a recent situation, we were chugging along happily with pg streaming replication.\r\n\r\nAt some point, under heavy write load, the streaming replication cut off, and our secondary replication method ([wal-e](https://github.com/wal-e/wal-e)) kicked in to catch up, until it was finally in-sync and streaming replication could resume.\r\n\r\nDuring this time, the postgres.replication_delay kept increasing, despite replication logs being applied, leading to a misleading graph:\r\n\r\n![screen shot 2015-01-24 at 11 32 49 am](https://cloud.githubusercontent.com/assets/529516/5888036/74cdd97e-a3bd-11e4-936a-4408dcc3b8a1.png)\r\n\r\nI suspect that the value being captured/reported in `pg_last_xact_replay_timestamp()` may only apply to timestamps being applied via streaming replication, thereby being slightly misleading.\r\n\r\nHere's what `pg_last_xact_replay_timestamp` does:\r\n\r\n> Get time stamp of last transaction replayed during recovery. This is the time at which the commit or abort WAL record for that transaction was generated on the primary. If no transactions have been replayed during recovery, this function returns NULL. Otherwise, if recovery is still in progress this will increase monotonically. If recovery has completed then this value will remain static at the value of the last transaction applied during that recovery. When the server has been started normally without recovery the function returns NULL.\r\n\r\nAnother way to examine replication delay is using a few of other functions:\r\n\r\n- pg_last_xlog_receive_location:\r\n\r\n   > Get last transaction log location received and synced to disk by streaming replication. While streaming replication is in progress this will increase monotonically. If recovery has completed this will remain static at the value of the last WAL record received and synced to disk during recovery. If streaming replication is disabled, or if it has not yet started, the function returns NULL.\r\n\r\n- pg_last_xlog_replay_location:\r\n\r\n   > Get last transaction log location replayed during recovery. If recovery is still in progress this will increase monotonically. If recovery has completed then this value will remain static at the value of the last WAL record applied during that recovery. When the server has been started normally without recovery the function returns NULL.\r\n\r\nThis should accurately capture replication lag in bytes applied:\r\n```sql\r\nSELECT pg_xlog_location_diff(pg_last_xlog_receive_location(), pg_last_xlog_replay_location())\r\n    AS replication_delay_bytes;\r\n```\r\nNote: `pg_xlog_location_diff` was introduced in PG 9.2 onwards. Some have [backported a function](https://vibhorkumar.wordpress.com/2013/02/18/pg_xlog_location_diff-function-for-postgreqsqlppas/) to perform the same, not sure I'd want to add a function to someone else's DB.\r\n\r\nI'm still not certain of how to best translate the bytes diffed to time, however this might be a good addition to have bytes lag in any case.\r\n\r\nFurther, an evolved version of the current `replication_delay` metric might be this:\r\n```sql\r\nSELECT CASE WHEN pg_last_xlog_receive_location() = pg_last_xlog_replay_location() \r\n            THEN 0 \r\n            ELSE GREATEST (0, EXTRACT (EPOCH FROM now() - pg_last_xact_replay_timestamp())) \r\n            END\r\n    AS replication_delay;\r\n```\r\n\r\nAs now we will only report a timestamp of the receive doesn't match the replay, meaning there must be a byte difference.\r\n\r\nI'm still not certain this will improve the visible lag graph as shown above, as the reported lag will still be reflecting the timestamp of the last transaction applied, but it would likely smooth out a replication delay graph during normal operations, removing the 0.01 second values being reported, since of there are no bytes lagging, we'll get 0.\r\n\r\nReference:\r\nhttp://www.postgresql.org/docs/9.2/static/functions-admin.html\r\n"}}