Upgrade to Pro — share decks privately, control downloads, hide ads and more …

Lessons Learned the Hard Way: Postgres in Production at GoCardless (PGDay UK Edition)

Lessons Learned the Hard Way: Postgres in Production at GoCardless (PGDay UK Edition)

Talk video: https://www.youtube.com/watch?v=Tu-cf-Jki60

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!

Chris Sinjakli

July 05, 2016
Tweet

More Decks by Chris Sinjakli

Other Decks in Programming

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. An app perspective

    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. Many guides on
    safe DDL

    View Slide

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

    View Slide

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

    View Slide

  25. The lock queue

    View Slide

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

    View Slide

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

    View Slide

  28. -- 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

  29. View Slide

  30. 15 seconds of API
    downtime

    View Slide

  31. Don’t OLAP
    where you OLTP

    View Slide

  32. Online
    Analytical
    Processing

    View Slide

  33. Online
    Transaction
    Processing

    View Slide

  34. Set appropriate
    bounds on the system

    View Slide

  35. SET lock_timeout…
    SET statement_timeout…

    View Slide

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

    View Slide

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

    View Slide

  38. log_lock_waits = on

    View Slide

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

    View Slide

  40. Not big data

    View Slide

  41. 2 hours chasing timeouts

    View Slide

  42. Oops

    View Slide


  43. 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

  44. A runaway analytics
    query

    View Slide

  45. Near miss

    View Slide

  46. Set appropriate
    bounds on the system

    View Slide

  47. temp_file_limit = … # size in kB

    View Slide

  48. But…

    View Slide

  49. Data growth

    View Slide

  50. Measure as you
    approach the limit

    View Slide

  51. But…

    View Slide

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

    View Slide

  53. ALTER SYSTEM SET temp_file_limit = -1; # disable
    CREATE INDEX pay_merch ON payments (merchant_id);
    ALTER SYSTEM SET temp_file_limit = …; # re-enable

    View Slide

  54. Per-session
    temp_file_limit?

    View Slide

  55. Resource utilisation
    ORMs
    Clustering

    View Slide

  56. 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(<<-SQL, 'SCHEMA')
    + 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
    '❤

    View Slide

  156. Questions?
    '❤
    @ChrisSinjo
    @GoCardlessEng

    View Slide

  157. Image credits
    • Heart emoji - https://github.com/mozilla/fxemoji/blob/
    9f68ca9c5bc51521f9ffe284e00ba8b7308e2c41/svgs/
    FirefoxEmoji/u2764-redheart.svg
    • Elephants - https://www.flickr.com/photos/makeitkenya/
    22047623331/
    • Campfire - https://www.flickr.com/photos/csakkarin/
    15499732208/
    • Detour - https://www.flickr.com/photos/wwward0/8257660963/
    • Kitten - https://www.flickr.com/photos/aigle_dore/7787096102

    View Slide

  158. 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

  159. 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

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

    View Slide

  161. 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

  162. 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

  163. 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
    • Scott Andreas' tweet about investigating things - https://
    twitter.com/cscotta/status/535898821914419200

    View Slide

  164. 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

  165. 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

  166. 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