telemetry (facebookincubator#440)

Summary:
Pull Request resolved: facebookincubator#440

Traces are written to Scuba glean_glass_server_events and visualised with Chrome (Perfetto)

{F1477527085}
https://fburl.com/scuba/glean_glass_server_events/gkhqrmoo

Right now only the following things are instrumented:

* The top level Thrift Handler
* documentSymbolsList/Index

RFC:

* would this be useful to debug Glass performance on individual requests?
* any concerns about running it in production?

One limitation is tracing inside Haxl computations. Would need a bit more work to instrument the Haxl datasource. Once that's done, it would theoretically be possible to carry the instrumentation through to the Glean server and have whole-system traces. But that's probably overkill.

I'll clean up the code and test the OSS build when/if there is consensus to land it

Reviewed By: josefs

Differential Revision: D55698252

fbshipit-source-id: ccd7c41345fcb2a54e5c3de6ed68912797516e6d

glean.cabal.in

@@ -1270,6 +1270,7 @@ library glass-lib
         Glean.Glass.SymbolKind
         Glean.Glass.SymbolMap
         Glean.Glass.SymbolSig
+        Glean.Glass.Tracing
         Glean.Glass.Utils
         Glean.Glass.Visibility
         Glean.Glass.XRefs

glean/glass/Glean/Glass/Env.hs

@@ -13,6 +13,7 @@ module Glean.Glass.Env
     Config(..),
     setSnapshotBackend,
     setSourceControl,
+    setTracer,
 
     -- * Session resources
     Env(..),
@@ -37,6 +38,7 @@ import Glean.Glass.Base (RepoMapping)
 import Glean.Glass.Repos (GleanDBInfo)
 import Glean.Glass.SnapshotBackend ( SnapshotBackend(..) )
 import Glean.Glass.SourceControl
+import Glean.Glass.Tracing (GlassTracer)
 
 -- | Init-time configuration
 data Config = Config
@@ -51,6 +53,7 @@ data Config = Config
   , numWorkerThreads :: Maybe Int
   , snapshotBackend :: EventBaseDataplane -> Some SnapshotBackend
   , sourceControl :: EventBaseDataplane -> Some SourceControl
+  , tracer :: GlassTracer
   }
 
 setSnapshotBackend
@@ -64,6 +67,9 @@ setSourceControl
 setSourceControl sourceControl config =
   config { sourceControl = sourceControl }
 
+setTracer :: GlassTracer -> Config -> Config
+setTracer tracer config = config{ tracer = tracer }
+
 -- | Read-only, scoped, dynamic resources.
 data Env = Env
   { evp :: EventBaseDataplane
@@ -77,6 +83,7 @@ data Env = Env
   , gleanDB :: Maybe Glean.Repo -- if provided, use as target Glean DB
   , repoMapping :: RepoMapping
   , sourceControl :: Some SourceControl
+  , tracer :: GlassTracer
   }
 
 -- | A backend to create incremental databases

glean/glass/Glean/Glass/Handler.hs

@@ -136,6 +136,8 @@ import Glean.Glass.SnapshotBackend
     SnapshotStatus() )
 import qualified Glean.Glass.SnapshotBackend as Snapshot
 import Glean.Glass.SymbolKind (findSymbolKind)
+import Glean.Glass.Env (Env (tracer))
+import Glean.Glass.Tracing (GlassTracer, traceSpan)
 
 -- | Runner for methods that are keyed by a file path
 runRepoFile
@@ -175,7 +177,7 @@ documentSymbolListX env r opts =
   fst3 <$>
     runRepoFile
       "documentSymbolListX"
-      fetchSymbolsAndAttributes
+      (fetchSymbolsAndAttributes (tracer env))
       env r opts
 
 -- | Same as documentSymbolList() but construct a line-indexed map for easy
@@ -189,7 +191,7 @@ documentSymbolIndex env r opts =
   fst3 <$>
     runRepoFile
       "documentSymbolIndex"
-      fetchDocumentSymbolIndex
+      (fetchDocumentSymbolIndex (tracer env))
       env r opts
 
 -- | Symbol-based find-refernces.
@@ -886,19 +888,22 @@ withEntity f scsrepo lang toks = do
 
 fetchSymbolsAndAttributesGlean
   :: Glean.Backend b
-  => Some SourceControl
+  => GlassTracer
+  -> Some SourceControl
   -> RepoMapping
   -> GleanDBInfo
   -> DocumentSymbolsRequest
   -> RequestOptions
   -> GleanBackend b
   -> Maybe Language
   -> IO ((DocumentSymbolListXResult, QueryEachRepoLog), Maybe ErrorLogger)
-fetchSymbolsAndAttributesGlean scm repoMapping dbInfo req opts be mlang = do
-  (res1, gLogs, elogs) <- fetchDocumentSymbols file mlimit
-    specificRev includeRefs includeXlangRefs be mlang
-  res2 <- addDynamicAttributes scm repoMapping dbInfo repo opts
-    file mlimit be res1
+fetchSymbolsAndAttributesGlean tracer scm repoMapping dbInfo req opts be mlang = do
+  (res1, gLogs, elogs) <- traceSpan tracer "fetchDocumentSymbols" $
+    fetchDocumentSymbols file mlimit
+      specificRev includeRefs includeXlangRefs be mlang
+  res2 <- traceSpan tracer "addDynamicAttributes" $
+    addDynamicAttributes scm repoMapping dbInfo repo opts
+      file mlimit be res1
   return ((res2, gLogs), elogs)
   where
     repo = documentSymbolsRequest_repository req
@@ -919,7 +924,8 @@ fetchSymbolsAndAttributesGlean scm repoMapping dbInfo req opts be mlang = do
 -- Find all symbols and refs in file and add all attributes
 fetchSymbolsAndAttributes
   :: (Glean.Backend b, SnapshotBackend snapshotBackend)
-  => Some SourceControl
+  => GlassTracer
+  -> Some SourceControl
   -> RepoMapping
   -> GleanDBInfo
   -> DocumentSymbolsRequest
@@ -929,13 +935,15 @@ fetchSymbolsAndAttributes
   -> Maybe Language
   -> IO ((DocumentSymbolListXResult, SnapshotStatus, QueryEachRepoLog)
         , Maybe ErrorLogger)
-fetchSymbolsAndAttributes scm repoMapping dbInfo req opts be
+fetchSymbolsAndAttributes tracer scm repoMapping dbInfo req opts be
     snapshotbe mlang = do
   res <- case mrevision of
     Just revision -> do
       (esnapshot, glean) <- Async.concurrently
-        (getSnapshot snapshotbe repo file (Just revision))
-        getFromGlean
+        (traceSpan tracer "getSnapshot" $
+          getSnapshot tracer snapshotbe repo file (Just revision))
+        (traceSpan tracer "getFromGlean"
+          getFromGlean)
       return $ case esnapshot of
         Right queryResult | not (isRevisionHit revision glean) ->
           ((queryResult, Snapshot.ExactMatch, QueryEachRepoUnrequested),
@@ -950,7 +958,7 @@ fetchSymbolsAndAttributes scm repoMapping dbInfo req opts be
       | all isNoSrcFileFact errorTy
       && not (requestOptions_exact_revision opts)
       -> do
-        bestSnapshot <- getSnapshot snapshotbe repo file Nothing
+        bestSnapshot <- getSnapshot tracer snapshotbe repo file Nothing
         case bestSnapshot of
           Right result ->
             return
@@ -965,7 +973,8 @@ fetchSymbolsAndAttributes scm repoMapping dbInfo req opts be
   where
     addStatus st ((res, gleanLog), mlogger) = ((res, st, gleanLog), mlogger)
     getFromGlean =
-      fetchSymbolsAndAttributesGlean scm repoMapping dbInfo req opts be mlang
+      fetchSymbolsAndAttributesGlean
+        tracer scm repoMapping dbInfo req opts be mlang
     file = documentSymbolsRequest_filepath req
     repo = documentSymbolsRequest_repository req
     mrevision = requestOptions_revision opts
@@ -1150,7 +1159,8 @@ documentSymbolsForLanguage mlimit _ includeRefs _ fileId = do
 -- With extra attributes loaded from any associated attr db
 fetchDocumentSymbolIndex
   :: (Glean.Backend b, SnapshotBackend snapshotBackend)
-  => Some SourceControl
+  => GlassTracer
+  -> Some SourceControl
   -> RepoMapping
   -> GleanDBInfo
   -> DocumentSymbolsRequest
@@ -1160,10 +1170,10 @@ fetchDocumentSymbolIndex
   -> Maybe Language
   -> IO ((DocumentSymbolIndex, SnapshotStatus, QueryEachRepoLog),
        Maybe ErrorLogger)
-fetchDocumentSymbolIndex scm repoMapping latest req opts be
+fetchDocumentSymbolIndex tracer scm repoMapping latest req opts be
     snapshotbe mlang = do
   ((DocumentSymbolListXResult{..}, status, gleanDataLog), merr1) <-
-    fetchSymbolsAndAttributes scm repoMapping latest req opts be snapshotbe mlang
+    fetchSymbolsAndAttributes tracer scm repoMapping latest req opts be snapshotbe mlang
 
   --  refs defs revision truncated digest = result
   let lineIndex = toSymbolIndex documentSymbolListXResult_references

glean/glass/Glean/Glass/Main.hs

@@ -16,6 +16,7 @@ module Glean.Glass.Main
   ) where
 
 
+import Control.Trace (traceMsg)
 import Facebook.Service ( runFacebookService' )
 import Facebook.Fb303 ( fb303Handler, withFb303 )
 import Thrift.Channel (Header)
@@ -57,6 +58,8 @@ import Glean.Glass.GlassService.Service ( GlassServiceCommand(..) )
 import Glean.Glass.Types
   ( GlassException (GlassException, glassException_reasons),
     GlassExceptionReason (GlassExceptionReason_exactRevisionNotAvailable))
+import Glean.Glass.Env (Env(tracer))
+import Glean.Glass.Tracing (GlassTrace(TraceCommand))
 
 kThriftCacheNoCache :: Text
 kThriftCacheNoCache = "nocache"
@@ -154,7 +157,8 @@ withCurrentRepoMapping env0 fn = do
 -- TODO: snapshot the env, rather than passing in the mutable fields
 --
 glassHandler :: Glass.Env -> GlassServiceCommand r -> IO r
-glassHandler env0 cmd = withCurrentRepoMapping env0 $ \env -> case cmd of
+glassHandler env0 cmd = withCurrentRepoMapping env0 $ \env ->
+  traceMsg (tracer env) (TraceCommand cmd) $ case cmd of
   SuperFacebookService r -> fb303Handler (Glass.fb303 env) r
 
   -- Listing symbols in files

glean/glass/Glean/Glass/Options.hs

@@ -38,6 +38,7 @@ configParser = do
   numWorkerThreads <- workerThreadsParser
   snapshotBackend <- pure (const $ Some NilSnapshotBackend)
   sourceControl <- pure (const (Some NilSourceControl))
+  tracer <- pure mempty
   return Glass.Config{configKey = Glass.defaultConfigKey, ..}
 
 portParser :: Parser Int

glean/glass/Glean/Glass/SnapshotBackend.hs

@@ -30,17 +30,19 @@ import Glean.Glass.Types (
       Path,
       RepoName(..),
       Path (..) )
+import Glean.Glass.Tracing (GlassTracer)
 
 class SnapshotBackend backend where
   getSnapshot
-    :: backend
+    :: GlassTracer
+    -> backend
     -> RepoName
     -> Path
     -> Maybe Revision
     -> IO (Either SnapshotStatus Types.DocumentSymbolListXResult)
 
 instance SnapshotBackend (Some SnapshotBackend) where
-  getSnapshot (Some backend) = getSnapshot backend
+  getSnapshot t (Some backend) = getSnapshot t backend
 
 data SnapshotStatus
   = Unrequested
@@ -64,4 +66,4 @@ snapshotBackendParser = Some NilSnapshotBackend <$ (option auto (mconcat
 data NilSnapshotBackend = NilSnapshotBackend
 
 instance SnapshotBackend NilSnapshotBackend where
-  getSnapshot _ _ _ _ = return $ Left Unrequested
+  getSnapshot _ _ _ _ _ = return $ Left Unrequested

glean/glass/Glean/Glass/Tracing.hs

@@ -0,0 +1,80 @@
+{-
+  Copyright (c) Meta Platforms, Inc. and affiliates.
+  All rights reserved.
+
+  This source code is licensed under the BSD-style license found in the
+  LICENSE file in the root directory of this source tree.
+-}
+
+{-# OPTIONS_GHC -Wno-unused-matches #-}
+module Glean.Glass.Tracing
+  ( GlassTrace(..)
+  , GlassTracer
+  , traceSpan
+  , glassTraceEvent
+  ) where
+
+import Data.Text (Text)
+
+import Control.Trace (traceMsg, Tracer)
+
+import Glean.Glass.GlassService.Service as Glass
+import Glean.Glass.Types
+import Data.Aeson ( pairs, fromEncoding, toEncoding, KeyValue((.=)) )
+import Data.Text.Lazy (toStrict)
+import Data.Text.Lazy.Encoding (decodeUtf8)
+import Data.Binary.Builder ( toLazyByteString )
+
+type GlassTracer = Tracer GlassTrace
+
+traceSpan :: GlassTracer -> Text -> IO a -> IO a
+traceSpan tracer span = traceMsg tracer (TraceSpan span Nothing)
+
+data GlassTrace where
+  TraceCommand :: forall r . GlassServiceCommand r -> GlassTrace
+  TraceSpan :: !Text -> Maybe Text -> GlassTrace
+
+glassTraceEvent :: GlassTrace -> (Text, Maybe Text)
+glassTraceEvent (TraceSpan event args) = (event, args)
+glassTraceEvent (TraceCommand cmd) = case cmd of
+  Glass.SuperFacebookService r -> ("SuperFacebookService", Nothing)
+  Glass.DocumentSymbolListX DocumentSymbolsRequest{..} opts ->
+    ( "DocumentSymbolListX"
+    , json $ pairs $
+       "filepath" .= documentSymbolsRequest_filepath <>
+       "repository" .= documentSymbolsRequest_repository <>
+       "revision" .= requestOptions_revision opts
+    )
+  Glass.DocumentSymbolIndex DocumentSymbolsRequest{..} opts ->
+    ("DocumentSymbolIndex"
+    , json $ pairs $
+       "filepath" .= documentSymbolsRequest_filepath <>
+       "repository" .= documentSymbolsRequest_repository <>
+       "revision" .= requestOptions_revision opts
+    )
+  Glass.FindReferences r opts ->
+    ( "FindReferences" , json $ toEncoding r)
+  Glass.FindReferenceRanges r opts ->
+    ("FindReferenceRanges", json $ toEncoding r)
+  Glass.ResolveSymbolRange r opts ->
+    ("ResolveSymbolRange", json $ toEncoding r)
+  Glass.DescribeSymbol r opts ->
+    ("DescribeSymbol", json $ toEncoding r)
+  Glass.SearchSymbol r opts ->
+    ("SearchSymbol", json $ toEncoding r)
+  Glass.SearchRelated r opts req ->
+    ("SearchRelated", json $ toEncoding r)
+  Glass.SearchRelatedNeighborhood r opts req ->
+    ("SearchRelatedNeighborhood", json $ toEncoding r)
+  Glass.SearchBySymbolId r opts ->
+    ("SearchBySymbolId", json $ toEncoding r)
+  Glass.Index r ->
+    ("Index", json $ toEncoding r)
+  Glass.FileIncludeLocations r opts ->
+    ("FileIncludeLocations", json $ toEncoding r)
+  Glass.ClangUSRToDefinition r opts ->
+    ("ClangUSRToDefinition", json $ toEncoding r)
+
+  where
+    json =
+      Just . toStrict . decodeUtf8 . toLazyByteString . fromEncoding

glean/glass/test/Glean/Glass/Test/RequestOptions.hs

@@ -396,7 +396,7 @@ newtype MockSnapshotBackend = MockSnapshotBackend {
 }
 
 instance SnapshotBackend MockSnapshotBackend where
-  getSnapshot (MockSnapshotBackend get) repo path revision =
+  getSnapshot _ (MockSnapshotBackend get) repo path revision =
     call get repo path revision
 
 -- | Create a mock snapshot backend containing the given snapshots

glean/glass/test/regression/lib/Glean/Glass/Regression/Util.hs

@@ -47,5 +47,6 @@ withTestEnvScm backend scm f =
         , gleanDB = Nothing
         , repoMapping = fixedRepoMapping
         , sourceControl = scm
+        , tracer = mempty
         , ..
         }