Lessons Learned the Hard Way: Postgres in Production at GoCardless (GoCardless DevOps Meetup Edition)

From the beginning, GoCardless has used Postgres for the stuff that matters. It’s the primary store behind our APIs and dashboards.

After 5 years, it’s fair to say we’ve seen some things. From spikes in latency as resources run out, through the weird contortions ORMs put your database through, and on to the perils of running a high-availability cluster - this talk has it all.

In the talk, we’ll run through some war stories from the last two years at GoCardless. By gathering them together, we’ll spot some recurring themes, and hopefully avoid fighting the same battles again!

Transcript

1. Lessons learned the hard way
   Postgres in production at GoCardless
   @ChrisSinjo
   

   View Slide

2. GOCARDLESS
   

   View Slide

3. POST /cash/monies HTTP/1.1
   { amount: 100 }
   
   

   View Slide

4. High per-request
   

   View Slide

5. Uptime is
   

   View Slide

6. You will have
   different concerns
   

   View Slide

7. The distributed
   system as a whole
   

   View Slide

8. View Slide

9. View Slide

10. View Slide

11. View Slide

12. Learning through the
    medium of post-mortems
    

    View Slide

13. What is a post-mortem?
    https://www.infoq.com/articles/postmortems-etsy
    

    View Slide

14. Failure can be a great
    teacher
    

    View Slide

15. 5 stories
    

    View Slide

16. Resource utilisation
    ORMs
    Clustering
    

    View Slide

17. foreach(incident):
    What happened
    Something we learned
    Ideas you can use
    

    View Slide

18. 3 things to do
    

    View Slide

19. Resource utilisation
    ORMs
    Clustering
    

    View Slide

20. Incident 1
    The Fast Migration
    That Wasn’t
    

    View Slide

21. ~10-20 schema changes
    per-month
    

    View Slide

22. Problem: locks
    

    View Slide

23. Many guides on safe
    schema changes
    

    View Slide

24. Don’t ADD COLUMN with DEFAULT
    VALIDATE constraints after
    adding
    Add indexes CONCURRENTLY
    

    View Slide

25. ALTER TABLE payments
    ADD COLUMN refunded boolean;
    No DEFAULT
    

    View Slide

26. The lock queue
    

    View Slide

27. -- Slow query (AccessShare)
    SELECT DISTINCT(customer_id) FROM payments;
    

    View Slide

28. -- Slow query (AccessShare)
    SELECT DISTINCT(customer_id) FROM payments;
    -- Forces this to queue (AccessExclusive)
    ALTER TABLE payments ADD COLUMN refunded boolean;
    

    View Slide

29. -- Slow query (AccessShare)
    SELECT DISTINCT(customer_id) FROM payments;
    -- Forces this to queue (AccessExclusive)
    ALTER TABLE payments ADD COLUMN refunded boolean;
    -- Which blocks these (AccessShare)
    SELECT * FROM payments WHERE id = 123;
    

    View Slide

30. View Slide

31. 15 seconds of API
    downtime
    

    View Slide

32. Online
    Analytical
    Processing
    

    View Slide

33. Online
    Transaction
    Processing
    

    View Slide

34. Don’t OLAP
    where you OLTP
    

    View Slide

35. Set appropriate
    bounds on the system
    

    View Slide

36. SET lock_timeout…
    SET statement_timeout…
    

    View Slide

37. https://gocardless.com/blog/zero-downtime-postgres-migrations-a-little-help/
    

    View Slide

38. -- Wishlist
    SET transaction_timeout…
    -- In 9.6
    SET idle_in_transaction_session_timeout…
    

    View Slide

39. log_lock_waits = on
    

    View Slide

40. Incident 2
    Did we just use 1.5TB of disk?
    

    View Slide

41. Not big data
    

    View Slide

42. 2 hours chasing timeouts
    

    View Slide

43. Oops
    

    View Slide

44. …
    LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp23325.11166", size 1245184
    LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp23325.11165", size 8675328
    LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp10729.11129", size 47734784
    …
    

    View Slide

45. A runaway analytics
    query
    

    View Slide

46. Don’t OLAP
    where you OLTP
    

    View Slide

47. Near miss
    

    View Slide

48. Set appropriate
    bounds on the system
    

    View Slide

49. temp_file_limit = … # size in kB
    

    View Slide

50. But…
    

    View Slide

51. Data growth
    

    View Slide

52. Measure as you
    approach the limit
    

    View Slide

53. But…
    

    View Slide

54. > CREATE INDEX pay_merch ON payments (merchant_id);
    ERROR: temporary file size exceeds temp_file_limit
    

    View Slide

55. SET temp_file_limit = -1; # disable
    CREATE INDEX pay_merch ON payments (merchant_id);
    RESET temp_file_limit; # re-enable
    

    View Slide

56. Resource utilisation
    ORMs
    Clustering
    

    View Slide

57. Incident 3
    Revenge of the ORM
    

    View Slide

58. Postgres
    Client 1
    Client 2
    

    View Slide

59. Postgres
    Client 1
    Client 2
    Client 3
    Client 4
    Client 5
    

    View Slide

60. Postgres
    Client 1
    Client 2
    Client 3
    Client 4
    Client 5
    .
    .
    .
    

    View Slide

61. PgBouncer with
    transaction-pooling
    

    View Slide

62. Postgres
    Client 1
    Client 2
    Client 3
    Client 4
    Client 5
    PgBouncer
    

    View Slide

63. No session-level
    features
    

    View Slide

64. SET
    Session-level advisory locks
    Prepared statements
    

    View Slide

65. We prepared our
    apps for this
    

    View Slide

66. NoMethodError: undefined method
    'fields' for nil:NilClass
    
    

    View Slide

67. –Literally everyone on the internet
    “You should disable prepared statements.”
    

    View Slide

68. 3 days
    3 people
    

    View Slide

69. On deployment
    On violating constraints
    

    View Slide

70. tcpdump + Wireshark
    

    View Slide

71. A bunch of extra statements!!!
    

    View Slide

72. SET client_encoding TO "utf8";
    SET client_min_messages TO "panic";
    SET standard_conforming_strings = on;
    SET client_min_messages TO "warning";
    SET time zone "UTC";
    

    View Slide

73. SET client_encoding TO "utf8";
    SET client_min_messages TO "panic";
    SET standard_conforming_strings = on;
    SET client_min_messages TO "warning";
    SET time zone "UTC";
    

    View Slide

74. Postgres
    Client 1
    Client 2
    Client 3
    Client 4
    Client 5
    PgBouncer
    

    View Slide

75. Postgres
    Client 1 PgBouncer
    

    View Slide

76. Postgres
    Client 1 PgBouncer
    SET … "panic";
    SET … "warning";
    

    View Slide

77. Postgres
    Client 1 PgBouncer
    SET … "panic";
    SET … "warning";
    SET … "panic";
    

    View Slide

78. Postgres
    Client 1 PgBouncer
    SET … "panic";
    SET … "warning";
    SET … "panic";
    SET … "warning";
    

    View Slide

79. So what
    if client_min_messages
    is set to "panic"?
    

    View Slide

80. ERROR: duplicate key value violates
    unique constraint "index_users_on_email"
    

    View Slide

81. $ git show a456acb2f2
    commit a456acb2f2af8365eb9151c7cd2d5a10c189d191
    Author: Harry Marr
    Date: Wed Oct 28 16:30:02 2015 +0000
    Avoid disabling postgres errors
    # Enable standard-conforming strings if available.
    def set_standard_conforming_strings
    - old, self.client_min_messages = client_min_messages, 'panic'
    - execute('SET standard_conforming_strings = on', 'SCHEMA') rescue nil
    - ensure
    - self.client_min_messages = old
    + execute(<+ UPDATE pg_settings
    + SET setting = 'on'
    + WHERE name = 'standard_conforming_strings'
    + SQL
    end
    

    View Slide

82. https://gocardless.com/blog/the-troubleshooting-tales-issues-scaling-postgres-
    connections/
    

    View Slide

83. https://twitter.com/rbranson/status/675005104701870080
    

    View Slide

84. There’s a lot
    more than
    /usr/bin/postgresql
    

    View Slide

85. - PgBouncer
    - libpq
    - Ruby pg gem
    - ActiveRecord (ORM)
    

    View Slide

86. It’s just code
    

    View Slide

87. Don’t trust the ORM
    

    View Slide

88. Resource utilisation
    ORMs
    Clustering
    

    View Slide

89. How soon are we back online?
    Is all our data there?
    

    View Slide

90. What’s in a cluster?
    

    View Slide

91. Consensus
    State machine
    Health checks
    Actions
    

    View Slide

92. Pacemaker
    

    View Slide

93. Incident 4
    Sorry, I cannot hear you
    I’m kinda busy
    

    View Slide

94. It starts with a page
    

    View Slide

95. crm mon status - demote event for
    Postgresql on : OK
    

    View Slide

96. psql: FATAL: sorry, too many clients already
    

    View Slide

97. 30 seconds of API
    downtime
    

    View Slide

98. Roll back the last
    change
    

    View Slide

99. # Should only be set for schema migrations
    USE_DIRECT_PG_CONNECTION=true
    

    View Slide

100. What about
     superuser_reserved_connections?
     

     View Slide

101. 70
     Normal
     App
     

     View Slide

102. 70
     26
     Normal
     App
     Unused
     

     View Slide

103. 70
     3
     1
     26
     Normal
     App
     Unused
     Superuser (non-reserved)
     Superuser (reserved)
     

     View Slide

104. 70
     3
     1
     26
     Normal Incident
     App
     Unused
     Superuser (non-reserved)
     Superuser (reserved)
     App
     97
     

     View Slide

105. 70
     3
     1
     26
     3
     1
     Normal Incident
     App
     Unused
     Superuser (non-reserved)
     Superuser (reserved)
     App
     Superuser (rejected)
     Superuser (reserved)
     97
     

     View Slide

106. Set appropriate
     bounds on the system
     

     View Slide

107. View Slide

108. Incident 5
     What’s in a health check?
     

     View Slide

109. su postgres -c 'psql -c "select now()"'
     Change to the
     Postgres user
     Run a simple query
     Connect to the
     database
     

     View Slide

110. Humans in LDAP
     Robots locally
     

     View Slide

111. su postgres -c 'psql -c "select now()"'
     Postgres is a
     local user
     

     View Slide

112. Safe to
     restart
     an LDAP node,
     right?
     

     View Slide

113. Wrong
     

     View Slide

114. Cluster transition
     due to
     health-check timeout
     

     View Slide

115. su postgres -c 'psql -c "select now()"'
     

     View Slide

116. su postgres -c 'echo "hello"'
     Command doesn’t
     matter
     

     View Slide

117. Enter strace, ltrace
     

     View Slide

118. strace - print every system
     call made by a process
     

     View Slide

119. ltrace - same, but for
     C library calls
     

     View Slide

120. Opinion: the most useful
     debugging tool you can learn
     http://jvns.ca/blog/2015/04/14/strace-zine/
     

     View Slide

121. # strace su postgres -c 'echo "hello"'
     getuid() = 0
     # ltrace su postgres -c 'echo "hello"'
     getlogin() = "chris"
     getpwnam_r(…) # blocks
     

     View Slide

122. # strace su postgres -c 'echo "hello"'
     getuid() = 0
     # ltrace su postgres -c 'echo "hello"'
     getlogin() = "chris"
     getpwnam_r(…) # blocks
     !?
     

     View Slide

123. getlogin
     

     View Slide

124. the user name associated by the
     login activity with the controlling
     terminal of the current process
     

     View Slide

125. the user name associated by the
     login activity with the controlling
     terminal of the current process
     

     View Slide

126. $ ./test_getlogin
     User is: chris
     $ sudo -i
     # ./test_getlogin
     User is: chris
     

     View Slide

127. /var/run/utmp
     /proc//loginuid
     

     View Slide

128. # ps aux | grep '[p]acemakerd' | awk '{print $2}'
     9001
     

     View Slide

129. # ps aux | grep '[p]acemakerd' | awk '{print $2}'
     9001
     # cat /proc/9001/loginuid
     1234
     

     View Slide

130. # ps aux | grep '[p]acemakerd' | awk '{print $2}'
     9001
     # cat /proc/9001/loginuid
     1234
     # getent passwd 1234 | cut -d':' -f1
     chris
     

     View Slide

131. View Slide

132. View Slide

133. View Slide

134. service pacemaker restart
     changes the user
     

     View Slide

135. Hold up.
     What is su doing?
     

     View Slide

136. The code is subtle
     

     View Slide

137. Getting a passwd struct for
     the calling user
     

     View Slide

138. uid = getuid() 0 (root)
     

     View Slide

139. uid = getuid()
     login = getlogin()
     0 (root)
     chris
     

     View Slide

140. uid = getuid()
     login = getlogin()
     passwd = passwd_from_name(login)
     0 (root)
     chris
     {…}
     

     View Slide

141. uid = getuid()
     login = getlogin()
     passwd = passwd_from_name(login)
     if (passwd.uid == uid)
     return passwd
     0 (root)
     chris
     {…}
     0 == 1234
     

     View Slide

142. uid = getuid()
     login = getlogin()
     passwd = passwd_from_name(login)
     if (passwd.uid == uid)
     return passwd
     else
     return passwd_from_uid(uid)
     0 (root)
     chris
     {…}
     0 == 1234
     

     View Slide

143. Only does anything if you
     have duplicate UIDs
     

     View Slide

144. Why does the
     login activity matter?
     

     View Slide

145. There may be
     Reasons™
     

     View Slide

146. Set appropriate
     bounds on the system
     

     View Slide

147. bind_timelimit
     

     View Slide

148. There’s a lot
     more than
     /usr/bin/postgresql
     

     View Slide

149. Run game days
     https://stripe.com/blog/game-day-exercises-at-stripe
     

     View Slide

150. 3 things to do
     

     View Slide

151. Watch the logs
     Set appropriate bounds
     Check what your ORM’s up to
     

     View Slide

152. And two thoughts…
     

     View Slide

153. Operating a database is about
     much more than the database itself
     

     View Slide

154. https://twitter.com/cscotta/status/535898821914419200
     

     View Slide

155. Thank you
     '❤
     @ChrisSinjo
     @GoCardlessEng
     

     View Slide

156. Questions?
     '❤
     @ChrisSinjo
     @GoCardlessEng
     

     View Slide

157. We’re hiring
     '❤
     @ChrisSinjo
     @GoCardlessEng
     

     View Slide

158. Image credits
     • Heart emoji - https://github.com/mozilla/fxemoji/blob/
     9f68ca9c5bc51521f9ffe284e00ba8b7308e2c41/svgs/
     FirefoxEmoji/u2764-redheart.svg
     • Elephants - https://www.flickr.com/photos/makeitkenya/
     22047623331/
     • Kitten - https://www.flickr.com/photos/aigle_dore/7787096102
     

     View Slide

159. References (Incident 1)
     • Safe Operations For High Volume PostgreSQL (Braintree) -
     https://www.braintreepayments.com/blog/safe-operations-for-
     high-volume-postgresql/
     • Zero-downtime Postgres migrations - the hard parts - https://
     gocardless.com/blog/zero-downtime-postgres-migrations-the-
     hard-parts/
     • Zero-downtime Postgres migrations - a little help - https://
     gocardless.com/blog/zero-downtime-postgres-migrations-a-little-
     help/
     

     View Slide

160. References (Incident 1)
     • Postgres 9.5 Client Connection Defaults (lock_timeout,
     statement_timeout) - https://www.postgresql.org/docs/9.5/
     static/runtime-config-client.html
     • Postgres 9.6 Client Connection Defaults
     (idle_in_transaction_session_timeout) - https://
     www.postgresql.org/docs/9.5/static/runtime-config-client.html
     • Postgres 9.5 Error Reporting and Logging (log_lock_waits) -
     https://www.postgresql.org/docs/9.5/static/runtime-config-
     logging.html
     

     View Slide

161. References (Incident 2)
     • Postgres 9.5 Resource Consumption (temp_file_limit) - https://
     www.postgresql.org/docs/current/static/runtime-config-
     resource.html
     

     View Slide

162. References (Incident 3)
     • PgBouncer feature matrix for pooling modes - https://
     wiki.postgresql.org/wiki/
     PgBouncer#Feature_matrix_for_pooling_modes
     • The Troubleshooting Tales: issues scaling Postgres connections - https://
     gocardless.com/blog/the-troubleshooting-tales-issues-scaling-postgres-
     connections/
     • Rails commit that fixed client_min_messages issue - https://github.com/
     rails/rails/commit/a456acb2f2af8365eb9151c7cd2d5a10c189d191
     • Rick Branson's tweet about the same problem in Django - https://
     twitter.com/rbranson/status/675005104701870080
     

     View Slide

163. References (Incident 4)
     • Postgres 9.5 Connections and Authentication
     (superuser_reserved_connections) - https://
     www.postgresql.org/docs/9.5/static/runtime-config-
     connection.html
     

     View Slide

164. References (Incident 5)
     • Julia Evans' strace zine - http://jvns.ca/blog/2015/04/14/
     strace-zine/
     • Game Day Exercises at Stripe: Learning from `kill -9` - https://
     stripe.com/blog/game-day-exercises-at-stripe
     

     View Slide

165. References (Incident 5)
     • Current code in `su` to look up user - https://github.com/
     shadow-maint/shadow/blob/
     ef45bb2496182b5df90ad0323bef75d1a5d69887/contrib/
     pwdauth.c#L127
     • Much older similar code in `su` (1994 or earlier) - https://
     github.com/freebsd/freebsd/blob/
     b5c3fb9427806b740f7df3e43a1513e1f5fa840b/usr.bin/su/
     su.c#L255
     

     View Slide

166. References (Incident 5)
     • getuid manual - http://pubs.opengroup.org/onlinepubs/
     009695399/functions/getuid.html
     • getlogin manual - http://pubs.opengroup.org/onlinepubs/
     009695399/functions/getlogin.html
     • getpwnam manual - http://pubs.opengroup.org/onlinepubs/
     9699919799/functions/getpwnam.html
     • getpwuid manual - http://pubs.opengroup.org/onlinepubs/
     009695399/functions/getpwuid.html
     

     View Slide

167. References (Misc)
     • Practical Postmortems at Etsy - https://www.infoq.com/articles/
     postmortems-etsy
     • Scott Andreas' tweet about investigating things - https://
     twitter.com/cscotta/status/535898821914419200
     

     View Slide