Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

CPU usage while idle #1076

Closed
steve-chavez opened this issue Mar 1, 2018 · 3 comments · Fixed by #2298
Closed

CPU usage while idle #1076

steve-chavez opened this issue Mar 1, 2018 · 3 comments · Fixed by #2298
Labels
perf

Comments

@steve-chavez
Copy link
Member

steve-chavez commented Mar 1, 2018 •
edited
Loading

Testing this on an Archlinux x64 - i7 4790 - 8GB RAM, when running top -p $(pgrep postgrest) about every 1 sec I see a %CPU 0.7 usage.

Did a profile on an idle postgrest running about 5 mins and I got:

Idle profile 
     postgrest +RTS -N -I2 -p -h -RTS config

total time  =        0.03 secs   (31 ticks @ 1000 us, 1 processor)

total alloc =   5,617,728 bytes  (excludes profiling overheads)


COST CENTRE          MODULE                         SRC                                                        %time %alloc


MAIN                 MAIN                                                                             61.3    9.7

reaper               Data.Pool                      Data/Pool.hs:(206,1)-(218,65)                               19.4    3.4

decodeUtf8With..go  Data.Text.Encoding             Data/Text/Encoding.hs:(133,7)-(152,34)                       3.2    0.0

">>=..succ'"        Data.Attoparsec.Internal.Types Data/Attoparsec/Internal/Types.hs:146:13-76                  3.2    0.5

foldr                Hasql.Private.Decoders.Result  library/Hasql/Private/Decoders/Result.hs:(211,3)-(227,31)    3.2    1.1

socket               Network.Socket                 Network/Socket.hsc:(345,1)-(366,15)                          3.2    0.0

getByte.byteInWord   Data.CritBit.Types.Internal    Data/CritBit/Types/Internal.hs:194:17-76                     3.2    0.0

allColumns.sql       PostgREST.DbStructure          src/PostgREST/DbStructure.hs:(335,3)-(503,32)                3.2   13.5

fmap                 Control.Monad.Trans.Either     src/Control/Monad/Trans/Either.hs:169:3-48                   0.0    1.4

<>.\                Control.Monad.Trans.Either     src/Control/Monad/Trans/Either.hs:(183,52)-(187,37)          0.0    1.5

<>..\              Control.Monad.Trans.Either     src/Control/Monad/Trans/Either.hs:(185,29)-(187,37)          0.0    5.9

getvalue'            Database.PostgreSQL.LibPQ      src/Database/PostgreSQL/LibPQ.hsc:(1328,1)-(1336,54)         0.0    1.7

getvalue'.\          Database.PostgreSQL.LibPQ      src/Database/PostgreSQL/LibPQ.hsc:(1329,30)-(1336,54)        0.0    3.8

nonNullValue         Hasql.Private.Decoders.Row     library/Hasql/Private/Decoders/Row.hs:65:3-54                0.0    1.2

decode               Hasql.Private.Decoders.Row     library/Hasql/Private/Decoders/Row.hs:56:36-92               0.0   12.4

value                Hasql.Private.Decoders.Row     library/Hasql/Private/Decoders/Row.hs:(44,3)-(57,33)         0.0    8.7

pure                 Hasql.Private.Decoders.Row     library/Hasql/Private/Decoders/Row.hs:11:22-32               0.0    2.7

reaper.\             Data.Pool                      Data/Pool.hs:(210,37)-(218,65)                               0.0    1.7

decodeColumns.colRow PostgREST.DbStructure          src/PostgREST/DbStructure.hs:(74,3)-(83,34)                  0.0    1.2

allRelations.sql     PostgREST.DbStructure          src/PostgREST/DbStructure.hs:(522,3)-(546,44)                0.0    1.7

allPrimaryKeys.sql   PostgREST.DbStructure          src/PostgREST/DbStructure.hs:(563,3)-(663,70)                0.0    7.5

allSynonyms.sql      PostgREST.DbStructure          src/PostgREST/DbStructure.hs:(674,3)-(742,6)                 0.0    3.8


That tells the Data.Pool(hasql pool dependency) reaper is the one using the CPU while idle, I increased the Pool timeout to 3600 to see if it helped but still got same 0.7% CPU usage:

3600 pool timeout profile 
     postgrest +RTS -N -I2 -p -h -RTS config

total time  =        0.04 secs   (43 ticks @ 1000 us, 1 processor)

total alloc =   6,154,576 bytes  (excludes profiling overheads)


COST CENTRE                           MODULE                         SRC                                                    %time %alloc


MAIN                                  MAIN                                                                         46.5    8.6

reaper                                Data.Pool                      Data/Pool.hs:(206,1)-(218,65)                           20.9    9.4

reaper.\                              Data.Pool                      Data/Pool.hs:(210,37)-(218,65)                           4.7    0.8

reaper.isStale                        Data.Pool                      Data/Pool.hs:209:7-62                                    4.7    3.5

">>=."                               Data.Attoparsec.Internal.Types Data/Attoparsec/Internal/Types.hs:(146,9)-(147,44)       2.3    0.6

<>..\                               Control.Monad.Trans.Either     src/Control/Monad/Trans/Either.hs:(185,29)-(187,37)      2.3    5.4

basicUnsafeIndexM                     Data.Vector                    Data/Vector.hs:277:3-62                                  2.3    0.1

sendQueryPrepared.(...)               Database.PostgreSQL.LibPQ      src/Database/PostgreSQL/LibPQ.hsc:1699:12-80             2.3    0.0

nonNullValue                          Hasql.Private.Decoders.Row     library/Hasql/Private/Decoders/Row.hs:65:3-54            2.3    1.1

decode                                Hasql.Private.Decoders.Row     library/Hasql/Private/Decoders/Row.hs:56:36-92           2.3   11.3

throwSocketErrorIfMinus1RetryMayBlock Network.Socket.Internal        Network/Socket/Internal.hsc:(161,1)-(162,53)             2.3    0.0

getAddrInfo....\                   Network.Socket                 Network/Socket.hsc:(1460,36)-(1470,43)                   2.3    0.0

allColumns.sql                        PostgREST.DbStructure          src/PostgREST/DbStructure.hs:(335,3)-(503,32)            2.3   12.3

allPrimaryKeys.sql                    PostgREST.DbStructure          src/PostgREST/DbStructure.hs:(563,3)-(663,70)            2.3    6.9

fmap                                  Control.Monad.Trans.Either     src/Control/Monad/Trans/Either.hs:169:3-48               0.0    1.3

<>.\                                 Control.Monad.Trans.Either     src/Control/Monad/Trans/Either.hs:(183,52)-(187,37)      0.0    1.4

getvalue'                             Database.PostgreSQL.LibPQ      src/Database/PostgreSQL/LibPQ.hsc:(1328,1)-(1336,54)     0.0    1.6

getvalue'.\                           Database.PostgreSQL.LibPQ      src/Database/PostgreSQL/LibPQ.hsc:(1329,30)-(1336,54)    0.0    3.4

value                                 Hasql.Private.Decoders.Row     library/Hasql/Private/Decoders/Row.hs:(44,3)-(57,33)     0.0    7.9

pure                                  Hasql.Private.Decoders.Row     library/Hasql/Private/Decoders/Row.hs:11:22-32           0.0    2.5

decodeColumns.colRow                  PostgREST.DbStructure          src/PostgREST/DbStructure.hs:(74,3)-(83,34)              0.0    1.1

allRelations.sql                      PostgREST.DbStructure          src/PostgREST/DbStructure.hs:(522,3)-(546,44)            0.0    1.6

allSynonyms.sql                       PostgREST.DbStructure          src/PostgREST/DbStructure.hs:(674,3)-(742,6)             0.0    3.5


Then noticed that the Data.Pool reaper works every second, so removed the 3600 timeout and patched the threadDelay to 30 secs(just a number I got from a Rust pool) and now the reaper doesn't use CPU significantly(again a 5 mins profile while idle):

30 secs reaper profile 
             postgrest +RTS -N -I2 -p -h -RTS config

      total time  =        0.01 secs   (7 ticks @ 1000 us, 1 processor)
      total alloc =   4,844,528 bytes  (excludes profiling overheads)

    COST CENTRE          MODULE                        SRC                                                        %time %alloc

    MAIN                 MAIN                          <built-in>                                                  14.3    1.1
    getvalue'            Database.PostgreSQL.LibPQ     src/Database/PostgreSQL/LibPQ.hsc:(1328,1)-(1336,54)        14.3    2.0
    getResult            Database.PostgreSQL.LibPQ     src/Database/PostgreSQL/LibPQ.hsc:(1764,1)-(1768,69)        14.3    0.1
    decode               Hasql.Private.Decoders.Row    library/Hasql/Private/Decoders/Row.hs:56:36-92              14.3   14.3
    pure                 Hasql.Private.Decoders.Row    library/Hasql/Private/Decoders/Row.hs:11:22-32              14.3    3.1
    getAddrInfo.\.\.\.\  Network.Socket                Network/Socket.hsc:(1460,36)-(1470,43)                      14.3    0.0
    ident.go             Data.Configurator.Syntax      Data/Configurator/Syntax.hs:(89,3)-(98,23)                  14.3    0.0
    CAF                  GHC.IO.Handle.FD              <entire-module>                                              0.0    1.1
    decodeUtf8With.\     Data.Text.Encoding            Data/Text/Encoding.hs:(132,59)-(153,35)                      0.0    1.1
    fmap                 Control.Monad.Trans.Either    src/Control/Monad/Trans/Either.hs:169:3-48                   0.0    1.7
    <*>.\                Control.Monad.Trans.Either    src/Control/Monad/Trans/Either.hs:(183,52)-(187,37)          0.0    1.7
    <*>.\.\              Control.Monad.Trans.Either    src/Control/Monad/Trans/Either.hs:(185,29)-(187,37)          0.0    6.9
    getvalue'.\          Database.PostgreSQL.LibPQ     src/Database/PostgreSQL/LibPQ.hsc:(1329,30)-(1336,54)        0.0    4.4
    foldr                Hasql.Private.Decoders.Result library/Hasql/Private/Decoders/Result.hs:(211,3)-(227,31)    0.0    1.2
    nonNullValue         Hasql.Private.Decoders.Row    library/Hasql/Private/Decoders/Row.hs:65:3-54                0.0    1.4
    value                Hasql.Private.Decoders.Row    library/Hasql/Private/Decoders/Row.hs:(44,3)-(57,33)         0.0   10.1
    allTables.sql        PostgREST.DbStructure         src/PostgREST/DbStructure.hs:(312,3)-(329,40)                0.0    1.0
    allColumns.sql       PostgREST.DbStructure         src/PostgREST/DbStructure.hs:(335,3)-(503,32)                0.0   15.7
    decodeColumns.colRow PostgREST.DbStructure         src/PostgREST/DbStructure.hs:(74,3)-(83,34)                  0.0    1.3
    allRelations.sql     PostgREST.DbStructure         src/PostgREST/DbStructure.hs:(522,3)-(546,44)                0.0    2.0
    allPrimaryKeys.sql   PostgREST.DbStructure         src/PostgREST/DbStructure.hs:(563,3)-(663,70)                0.0    8.7
    allSynonyms.sql      PostgREST.DbStructure         src/PostgREST/DbStructure.hs:(674,3)-(742,6)                 0.0    4.4
    procsSqlQuery        PostgREST.DbStructure         src/PostgREST/DbStructure.hs:(171,1)-(187,2)                 0.0    1.1

Still got around 1.5%/2.0% at around 20 secs when running it though, I disabled idle GC by compiling with I0 and now CPU usage is 0.0% most of the time(getting 0.7% usage at around 6 mins).

The idle CPU usage matters when having multiple postgrest instances adding up infrastructure costs.
@mbj
Copy link

mbj commented Mar 1, 2018

I suggest to check strace if these processes create any meaningful system calls helping you to identify what work postgres is doing.

@jfischoff
Copy link

Disabling the idle GC is a common practice so +1 to that as a default.

@jberryman
Copy link

See also #565

@steve-chavez steve-chavez mentioned this issue May 31, 2022
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
perf
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

fix: disable parallel GC for perf on high-core CPU steve-chavez/postgrest
4 participants
@mbj @jfischoff @jberryman @steve-chavez