add: log schema cache queries' timings
This adds a new log line that shows each schema cache query time individually, only on `log-level=debug`. Like so: ``` $ PGRST_LOG_LEVEL=debug postgrest-with-pg-17 -f test/spec/fixtures/load.sql postgrest-run .... 10/Apr/2026:21:48:45 -0500: Schema cache queried in 192.2 milliseconds 10/Apr/2026:21:48:45 -0500: tables: 72.027 ms, keydeps: 20.118 ms, rels: 6.189 ms, funcs: 35.010 ms, comprels: 4.319 ms, dreps: 1.614 ms, mhandlers: 7.419 ms, tzones: 43.025 ms ``` This helps debug specific schema cache queries being slow like on https://github.com/PostgREST/postgrest/issues/4613#issuecomment-4210191065 and https://github.com/PostgREST/postgrest/issues/3046#issuecomment-3469059948. It also closes https://github.com/PostgREST/postgrest/issues/3215, which main motivation was to find out which query is slow. Implementation details --------------------- To time each query inside a transaction in pure SQL, we do: ```sql -- start timer select set_config('pgrst.tmp_x', clock_timestamp()::text, false); -- run the query select <query> -- end timer select set_config('pgrst.tmp_x', (clock_timestamp() - current_setting('pgrst.tmp_x', false)::timestamptz)::text, false); -- .... repeated for every query -- at the end we capture all the timings with select extract('milliseconds' from current_setting('pgrst.tmp_x', false)::interval), extract(..; ``` Considerations -------------- Only added this on `log-level=debug` because while the queries are fast and the data is valuable, it triples the amount of queries we run during schema cache refresh, which could be troublesome on slow networks. It's possible to reduce the amount of queries by starting and stopping timers in one statement, but this would still double the amount of queries and makes the code messy, doesn't seem worth it. Also it would pollute pg_stat_statements, it's only required to debug certain extreme cases anyway.
This commit is contained in:
steve-chavez
committed by
Steve Chavez
Steve Chavez
parent
6af77360d3
commit
bcc8998e5e
@@ -14,6 +14,7 @@ All notable changes to this project will be documented in this file. From versio
|
||||
- Add `Vary` header to responses by @develop7 in #4609
|
||||
- Add config `db-timezone-enabled` for optional querying of timezones by @taimoorzaeem in #4751
|
||||
- Log when the pool is released during schema cache reload on `log-level=debug` by @mkleczek in #4668
|
||||
- Log schema cache queries timings on `log-level=debug` by @steve-chavez in #4805
|
||||
|
||||
### Fixed
|
||||
|
||||
|
||||
@@ -11,6 +11,7 @@ Getting this metadata requires expensive queries. To avoid repeating this work,
|
||||
|
||||
- Schema cache queries have been optimized over time to stay fast, even on complex databases. You can see a summary of their execution time in :ref:`pgrst_logging` and :ref:`metrics`.
|
||||
- If the schema cache queries are slow, the most likely cause is *system catalog bloat*, see `issue#3212 <https://github.com/PostgREST/postgrest/issues/3212>`_ for more details.
|
||||
- You can turn the :ref:`log-level` to ``debug`` to see the time of each schema cache query.
|
||||
|
||||
.. _schema_reloading:
|
||||
|
||||
|
||||
@@ -350,12 +350,13 @@ retryingSchemaCacheLoad appState@AppState{stateObserver=observer, stateMainThrea
|
||||
-- IORef on putSchemaCache. This is why schema cache status is marked as pending here to signal the Admin server (using isPending) that we're on a recovery state.
|
||||
markSchemaCachePending appState
|
||||
putSchemaCache appState $ Just sCache
|
||||
(loadTime, summary) <- timeItT (evaluate $ showSummary sCache)
|
||||
-- Flush the pool after loading the schema cache to reset any stale session cache entries
|
||||
-- We do it after successfully querying the schema cache (because this can fail and during retries we would flush the pool repeatedly unnecessarily)
|
||||
-- and after marking sCacheStatus as pending,
|
||||
flushPool appState
|
||||
observer $ SchemaCacheQueriedObs resultTime
|
||||
observer . uncurry SchemaCacheLoadedObs =<< timeItT (evaluate $ showSummary sCache)
|
||||
observer $ SchemaCacheQueriedObs resultTime $ dbQueryTimings sCache
|
||||
observer $ SchemaCacheLoadedObs loadTime summary
|
||||
markSchemaCacheLoaded appState
|
||||
return $ Just sCache
|
||||
|
||||
|
||||
@@ -36,6 +36,7 @@ import PostgREST.Config (LogLevel (..), Verbosity (..))
|
||||
import PostgREST.Debounce (makeDebouncer)
|
||||
import PostgREST.Observation
|
||||
import PostgREST.Query (MainQuery (..))
|
||||
import PostgREST.SchemaCache (queryTimingsWLabels)
|
||||
|
||||
import qualified Data.ByteString.Lazy as LBS
|
||||
import qualified Data.Text as T
|
||||
@@ -168,8 +169,10 @@ observationMessages = \case
|
||||
<> " and "
|
||||
<> "db-extra-search-path=" <> T.intercalate "," extraPaths
|
||||
<> ". " <> jsonMessage usageErr
|
||||
SchemaCacheQueriedObs resultTime ->
|
||||
pure $ "Schema cache queried in " <> showMillis resultTime <> " milliseconds"
|
||||
SchemaCacheQueriedObs resultTime timings ->
|
||||
[ "Schema cache queried in " <> showMillis resultTime <> " milliseconds " ] <>
|
||||
let showTimings qt = [ T.intercalate ", " $ (\(l, v) -> T.decodeUtf8 l <> ": " <> v <> " ms") <$> queryTimingsWLabels qt ] in
|
||||
maybe mempty showTimings timings
|
||||
SchemaCacheLoadedObs resultTime summary ->
|
||||
[
|
||||
"Schema cache loaded " <> summary
|
||||
|
||||
@@ -18,6 +18,7 @@ import qualified Hasql.Pool.Observation as SQL
|
||||
import Network.HTTP.Types.Status (Status)
|
||||
import PostgREST.Config.PgVersion
|
||||
import PostgREST.Query (MainQuery)
|
||||
import PostgREST.SchemaCache (QueryTimings)
|
||||
|
||||
import Protolude hiding (toList)
|
||||
|
||||
@@ -31,7 +32,7 @@ data Observation
|
||||
| DBConnectedObs Text
|
||||
| SchemaCacheEmptyObs
|
||||
| SchemaCacheErrorObs (NonEmpty Text) [Text] SQL.UsageError
|
||||
| SchemaCacheQueriedObs Double
|
||||
| SchemaCacheQueriedObs Double (Maybe QueryTimings)
|
||||
| SchemaCacheLoadedObs Double Text
|
||||
| ConnectionRetryObs Int
|
||||
| DBListenStart (Maybe ByteString) (Maybe ByteString) Text Text -- host, port, version string, channel
|
||||
|
||||
@@ -24,10 +24,14 @@ module PostgREST.SchemaCache
|
||||
, querySchemaCache
|
||||
, showSummary
|
||||
, decodeFuncs
|
||||
, QueryTimings(..)
|
||||
, queryTimingsWLabels
|
||||
) where
|
||||
|
||||
import Data.Aeson ((.=))
|
||||
import qualified Data.Aeson as JSON
|
||||
import Data.Aeson ((.=))
|
||||
import qualified Data.Aeson as JSON
|
||||
|
||||
import qualified Data.ByteString.Char8 as BS
|
||||
import qualified Data.HashMap.Strict as HM
|
||||
import qualified Data.HashMap.Strict.InsOrd as HMI
|
||||
import qualified Data.Set as S
|
||||
@@ -40,7 +44,8 @@ import qualified Hasql.Transaction as SQL
|
||||
import Data.Functor.Contravariant ((>$<))
|
||||
import NeatInterpolation (trimming)
|
||||
|
||||
import PostgREST.Config (AppConfig (..))
|
||||
import PostgREST.Config (AppConfig (..),
|
||||
LogLevel (..))
|
||||
import PostgREST.Config.Database (TimezoneNames,
|
||||
toIsolationLevel)
|
||||
import PostgREST.SchemaCache.Identifiers (FieldName,
|
||||
@@ -85,10 +90,11 @@ data SchemaCache = SchemaCache
|
||||
-- Since index construction can be expensive, we build it once and store in the SchemaCache
|
||||
-- Haskell lazy evaluation ensures it's only built on first use and memoized afterwards
|
||||
, dbTablesFuzzyIndex :: TablesFuzzyIndex
|
||||
, dbQueryTimings :: Maybe QueryTimings -- ^ cached time for the time each query took when debugging
|
||||
} deriving (Show)
|
||||
|
||||
instance JSON.ToJSON SchemaCache where
|
||||
toJSON (SchemaCache tabs rels routs reps hdlers tzs _) = JSON.object [
|
||||
toJSON (SchemaCache tabs rels routs reps hdlers tzs _ _) = JSON.object [
|
||||
"dbTables" .= JSON.toJSON tabs
|
||||
, "dbRelationships" .= JSON.toJSON rels
|
||||
, "dbRoutines" .= JSON.toJSON routs
|
||||
@@ -98,7 +104,7 @@ instance JSON.ToJSON SchemaCache where
|
||||
]
|
||||
|
||||
showSummary :: SchemaCache -> Text
|
||||
showSummary (SchemaCache tbls rels routs reps mediaHdlrs tzs _) =
|
||||
showSummary (SchemaCache tbls rels routs reps mediaHdlrs tzs _ _) =
|
||||
T.intercalate ", "
|
||||
[ show (HM.size tbls) <> " Relations"
|
||||
, show (HM.size rels) <> " Relationships"
|
||||
@@ -152,20 +158,25 @@ maxDbTablesForFuzzySearch = 500
|
||||
querySchemaCache :: AppConfig -> SQL.Transaction SchemaCache
|
||||
querySchemaCache conf@AppConfig{..} = do
|
||||
SQL.sql "set local schema ''" -- This voids the search path. The following queries need this for getting the fully qualified name(schema.name) of every db object
|
||||
tabs <- SQL.statement conf $ allTables prepared
|
||||
keyDeps <- SQL.statement conf $ allViewsKeyDependencies prepared
|
||||
m2oRels <- SQL.statement mempty $ allM2OandO2ORels prepared
|
||||
funcs <- SQL.statement conf $ allFunctions prepared
|
||||
cRels <- SQL.statement mempty $ allComputedRels prepared
|
||||
reps <- SQL.statement conf $ dataRepresentations prepared
|
||||
mHdlers <- SQL.statement conf $ mediaHandlers prepared
|
||||
tabs <- sqlTimedStmt gucTbls conf $ allTables prepared
|
||||
keyDeps <- sqlTimedStmt gucKDeps conf $ allViewsKeyDependencies prepared
|
||||
m2oRels <- sqlTimedStmt gucRels mempty $ allM2OandO2ORels prepared
|
||||
funcs <- sqlTimedStmt gucFuncs conf $ allFunctions prepared
|
||||
cRels <- sqlTimedStmt gucCRels mempty $ allComputedRels prepared
|
||||
reps <- sqlTimedStmt gucDReps conf $ dataRepresentations prepared
|
||||
mHdlers <- sqlTimedStmt gucMHdrs conf $ mediaHandlers prepared
|
||||
tzones <- if configDbTimezoneEnabled
|
||||
then SQL.statement mempty $ timezones prepared
|
||||
then sqlTimedStmt gucTzones mempty $ timezones prepared
|
||||
else pure S.empty
|
||||
_ <-
|
||||
let sleepCall = SQL.Statement "select pg_sleep($1 / 1000.0)" (param HE.int4) HD.noResult prepared in
|
||||
for_ configInternalSCQuerySleep (`SQL.statement` sleepCall) -- only used for testing
|
||||
|
||||
qsTime <-
|
||||
if isLogDebug
|
||||
then Just <$> SQL.statement mempty (extractTimings configDbTimezoneEnabled prepared)
|
||||
else pure Nothing
|
||||
|
||||
let tabsWViewsPks = addViewPrimaryKeys tabs keyDeps
|
||||
rels = addInverseRels $ addM2MRels tabsWViewsPks $ addViewM2OAndO2ORels keyDeps m2oRels
|
||||
|
||||
@@ -183,11 +194,14 @@ querySchemaCache conf@AppConfig{..} = do
|
||||
-- Only build fuzzy index for schemas with a reasonable number of tables
|
||||
-- Fuzzy.FuzzySet is memory heavy we just don't use it for large schemas
|
||||
Fuzzy.fromList <$> HM.filter ((< maxDbTablesForFuzzySearch) . length) (HM.fromListWith (<>) ((qiSchema &&& pure . qiName) <$> HM.keys tabsWViewsPks))
|
||||
, dbQueryTimings = qsTime
|
||||
}
|
||||
where
|
||||
schemas = toList configDbSchemas
|
||||
prepared = configDbPreparedStatements
|
||||
delayEval confDelay result = maybe result (unsafePerformIO . (($> result) . (threadDelay . (1000 *) . fromIntegral))) confDelay
|
||||
isLogDebug = configLogLevel == LogDebug
|
||||
sqlTimedStmt = sqlTimedStatement isLogDebug
|
||||
|
||||
-- | overrides detected relationships with the computed relationships and gets the RelationshipsMap
|
||||
getOverrideRelationshipsMap :: [Relationship] -> [Relationship] -> RelationshipsMap
|
||||
@@ -221,6 +235,7 @@ removeInternal schemas dbStruct =
|
||||
, dbMediaHandlers = dbMediaHandlers dbStruct
|
||||
, dbTimezones = dbTimezones dbStruct
|
||||
, dbTablesFuzzyIndex = dbTablesFuzzyIndex dbStruct
|
||||
, dbQueryTimings = dbQueryTimings dbStruct
|
||||
}
|
||||
where
|
||||
hasInternalJunction ComputedRelationship{} = False
|
||||
@@ -1147,3 +1162,72 @@ nullableColumn = HD.column . HD.nullable
|
||||
|
||||
arrayColumn :: HD.Value a -> HD.Row [a]
|
||||
arrayColumn = column . HD.listArray . HD.nonNullable
|
||||
|
||||
{-
|
||||
- Times a sql statement inside a transaction, for this:
|
||||
-
|
||||
- 1. We start a timer: select set_config('pgrst.tmp_x', clock_timestamp()::text, false);
|
||||
- 2. Run the statement: select ....
|
||||
- 3. End the timer: select set_config('pgrst.tmp_x', (clock_timestamp() - current_setting('pgrst.tmp_x', false)::timestamptz)::text, false);
|
||||
-
|
||||
- We can do this for several statements inside the transaction. The timings are later captured at the end of the transaction with extractTimings.
|
||||
-}
|
||||
sqlTimedStatement :: Bool -> ByteString -> a -> SQL.Statement a b -> SQL.Transaction b
|
||||
sqlTimedStatement isLogDebug guc params stmt =
|
||||
if isLogDebug then
|
||||
SQL.sql sFrag >> SQL.statement params stmt <* SQL.sql eFrag
|
||||
else
|
||||
SQL.statement params stmt
|
||||
where
|
||||
sFrag = "select set_config('pgrst." <> guc <> "', clock_timestamp()::text, true)"
|
||||
eFrag = "select set_config('pgrst." <> guc <> "', (clock_timestamp() - current_setting('pgrst." <> guc <> "', false)::timestamptz)::text, true)"
|
||||
|
||||
-- Extract all the generated timings (see sqlTimedStatement) converting the value to milliseconds.
|
||||
extractTimings :: Bool -> Bool -> SQL.Statement () QueryTimings
|
||||
extractTimings hasTimezones = SQL.Statement sql HE.noParams decodeThem
|
||||
where
|
||||
qFrag setting = "extract('milliseconds' from current_setting('pgrst." <> setting <> "', false)::interval)::text"
|
||||
sql = "SELECT " <> BS.intercalate ","
|
||||
[ qFrag gucTbls, qFrag gucKDeps, qFrag gucRels
|
||||
, qFrag gucFuncs, qFrag gucCRels, qFrag gucDReps
|
||||
, qFrag gucMHdrs, if hasTimezones then qFrag gucTzones else "'0.0'"
|
||||
]
|
||||
decodeThem :: HD.Result QueryTimings
|
||||
decodeThem = HD.singleRow $
|
||||
QueryTimings
|
||||
<$> column HD.text <*> column HD.text <*> column HD.text
|
||||
<*> column HD.text <*> column HD.text <*> column HD.text
|
||||
<*> column HD.text <*> column HD.text
|
||||
|
||||
data QueryTimings = QueryTimings
|
||||
{ qtTables :: Text
|
||||
, qtKeyDeps :: Text
|
||||
, qtRels :: Text
|
||||
, qtFuncs :: Text
|
||||
, qtCRels :: Text
|
||||
, qtDReps :: Text
|
||||
, qtMHdrs :: Text
|
||||
, qtTzones :: Text
|
||||
} deriving (Show)
|
||||
|
||||
queryTimingsWLabels :: QueryTimings -> [(ByteString, Text)]
|
||||
queryTimingsWLabels qt =
|
||||
[ (gucTbls, qtTables qt)
|
||||
, (gucKDeps, qtKeyDeps qt)
|
||||
, (gucRels, qtRels qt)
|
||||
, (gucFuncs, qtFuncs qt)
|
||||
, (gucCRels, qtCRels qt)
|
||||
, (gucDReps, qtDReps qt)
|
||||
, (gucMHdrs, qtMHdrs qt)
|
||||
, (gucTzones, qtTzones qt)
|
||||
]
|
||||
|
||||
gucTbls, gucKDeps, gucRels, gucFuncs, gucCRels, gucDReps, gucMHdrs, gucTzones :: ByteString
|
||||
gucTbls = "tables"
|
||||
gucKDeps = "keydeps"
|
||||
gucRels = "rels"
|
||||
gucFuncs = "funcs"
|
||||
gucCRels = "comprels"
|
||||
gucDReps = "dreps"
|
||||
gucMHdrs = "mhandlers"
|
||||
gucTzones = "tzones"
|
||||
|
||||
@@ -1269,6 +1269,38 @@ def test_schema_cache_load_sleep_logs(defaultenv):
|
||||
assert 1000 < observed_ms < 2000
|
||||
|
||||
|
||||
@pytest.mark.parametrize("timezone_enabled", ["true", "false"])
|
||||
@pytest.mark.parametrize("level", ["crit", "error", "warn", "info", "debug"])
|
||||
def test_schema_cache_query_timings_log(level, timezone_enabled, defaultenv):
|
||||
"Schema cache query timings should be logged on log-level=debug."
|
||||
|
||||
env = {
|
||||
**defaultenv,
|
||||
"PGRST_LOG_LEVEL": level,
|
||||
# when this is disabled, it should log 0 for tzones
|
||||
"PGRST_DB_TIMEZONE_ENABLED": timezone_enabled,
|
||||
}
|
||||
# here we also capture the tzones: <value> ms
|
||||
log_pattern = re.compile(
|
||||
r".+: tables: [\d.]+ ms, keydeps: [\d.]+ ms, rels: [\d.]+ ms, funcs: [\d.]+ ms, comprels: [\d.]+ ms, dreps: [\d.]+ ms, mhandlers: [\d.]+ ms, tzones: ([\d.]+) ms"
|
||||
)
|
||||
|
||||
with run(env=env, no_startup_stdout=False) as postgrest:
|
||||
output = drain_stdout(postgrest)
|
||||
timing_matches = [
|
||||
match for line in output if (match := log_pattern.match(line))
|
||||
]
|
||||
|
||||
if level == "debug":
|
||||
assert len(timing_matches) == 1
|
||||
if timezone_enabled == "false":
|
||||
assert float(timing_matches[0].group(1)) == 0
|
||||
else:
|
||||
assert float(timing_matches[0].group(1)) > 0
|
||||
else:
|
||||
assert not timing_matches
|
||||
|
||||
|
||||
@pytest.mark.parametrize("dburi_type", ["no_params", "no_params_qmark", "with_params"])
|
||||
def test_get_pgrst_version_with_uri_connection_string(dburi_type, dburi, defaultenv):
|
||||
"The fallback_application_name should be added to the db-uri if it has a URI format"
|
||||
|
||||
Reference in New Issue
Block a user