diff --git a/CHANGELOG.md b/CHANGELOG.md index 43807eb01..77ffd13d2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -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 diff --git a/docs/references/schema_cache.rst b/docs/references/schema_cache.rst index 1199670fa..deb053181 100644 --- a/docs/references/schema_cache.rst +++ b/docs/references/schema_cache.rst @@ -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 `_ for more details. + - You can turn the :ref:`log-level` to ``debug`` to see the time of each schema cache query. .. _schema_reloading: diff --git a/src/PostgREST/AppState.hs b/src/PostgREST/AppState.hs index 55ee2de1d..fd2edd2f7 100644 --- a/src/PostgREST/AppState.hs +++ b/src/PostgREST/AppState.hs @@ -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 diff --git a/src/PostgREST/Logger.hs b/src/PostgREST/Logger.hs index 748a1bdc6..a43040137 100644 --- a/src/PostgREST/Logger.hs +++ b/src/PostgREST/Logger.hs @@ -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 diff --git a/src/PostgREST/Observation.hs b/src/PostgREST/Observation.hs index 89d28dabf..6a37daab6 100644 --- a/src/PostgREST/Observation.hs +++ b/src/PostgREST/Observation.hs @@ -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 diff --git a/src/PostgREST/SchemaCache.hs b/src/PostgREST/SchemaCache.hs index c928dac0d..cdc1e6930 100644 --- a/src/PostgREST/SchemaCache.hs +++ b/src/PostgREST/SchemaCache.hs @@ -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" diff --git a/test/io/test_io.py b/test/io/test_io.py index b0f4aef58..0cb58cf96 100644 --- a/test/io/test_io.py +++ b/test/io/test_io.py @@ -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: 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"