Log time spent consuming request bytes from socket. Closes hasura#3547

Add a new 'request_read_time' to the logging record. We also use 'withElapsedTime' to get proper monotonic clock for 'query_execution_time' as well.
jberryman · Jan 30, 2020 · 4198dee · 4198dee
1 parent 2350069
commit 4198dee
Show file tree

Hide file tree

Showing 2 changed files with 3 additions and 11 deletions.
diff --git a/server/src-lib/Hasura/Server/App.hs b/server/src-lib/Hasura/Server/App.hs
@@ -22,7 +22,6 @@ import qualified Data.ByteString.Lazy                   as BL
 import qualified Data.HashMap.Strict                    as M
 import qualified Data.HashSet                           as S
 import qualified Data.Text                              as T
-import qualified Data.Time.Clock                        as Clock
 import qualified Database.PG.Query                      as Q
 import qualified Network.HTTP.Client                    as HTTP
 import qualified Network.HTTP.Types                     as HTTP
@@ -227,16 +226,14 @@ mkSpockAction serverCtx qErrEncoder qErrModifier apiHandler = do
         res <- lift $ runReaderT (runExceptT $ handler parsedReq) handlerState
         return (res, Just parsedReq)
 
-    t2 <- liftIO Clock.getCurrentTime -- for measuring response time purposes
-
     -- apply the error modifier
     let modResult = fmapL qErrModifier result
 
     -- log and return result
     case modResult of
       Left err  -> let jErr = maybe (Left reqBody) (Right . toJSON) q
                    in logErrorAndResp (Just userInfo) requestId req jErr (isAdmin curRole) headers err
-      Right res -> logSuccessAndResp (Just userInfo) requestId req (fmap toJSON q) res (Just (t1, t2)) headers
+      Right res -> logSuccessAndResp (Just userInfo) requestId req (fmap toJSON q) res (Just (ioWaitTime, serviceTime)) headers
 
     where
       logger = scLogger serverCtx

diff --git a/server/src-lib/Hasura/Server/Logging.hs b/server/src-lib/Hasura/Server/Logging.hs
@@ -24,7 +24,6 @@ import           Data.Bits                 (shift, (.&.))
 import           Data.ByteString.Char8     (ByteString)
 import           Data.Int                  (Int64)
 import           Data.List                 (find)
-import           Data.Time.Clock
 import           Data.Word                 (Word32)
 import           Network.Socket            (SockAddr (..))
 import           System.ByteOrder          (ByteOrder (..), byteOrder)
@@ -222,7 +221,7 @@ mkHttpAccessLogContext
   -> Maybe CompressionType
   -> [HTTP.Header]
   -> HttpLogContext
-mkHttpAccessLogContext userInfoM reqId req res mTimeT compressTypeM headers =
+mkHttpAccessLogContext userInfoM reqId req res mTiming compressTypeM headers =
   let http = HttpInfoLog
              { hlStatus      = status
              , hlMethod      = bsToTxt $ Wai.requestMethod req
@@ -246,7 +245,6 @@ mkHttpAccessLogContext userInfoM reqId req res mTimeT compressTypeM headers =
   where
     status = HTTP.status200
     respSize = Just $ BL.length res
-    respTime = computeTimeDiff mTimeT
 
 mkHttpErrorLogContext
   :: Maybe UserInfo
@@ -259,7 +257,7 @@ mkHttpErrorLogContext
   -> Maybe CompressionType
   -> [HTTP.Header]
   -> HttpLogContext
-mkHttpErrorLogContext userInfoM reqId req err query mTimeT compressTypeM headers =
+mkHttpErrorLogContext userInfoM reqId req err query mTiming compressTypeM headers =
   let http = HttpInfoLog
              { hlStatus      = qeStatus err
              , hlMethod      = bsToTxt $ Wai.requestMethod req
@@ -297,9 +295,6 @@ mkHttpLog httpLogCtx =
       logLevel = bool LevelInfo LevelError isError
   in HttpLogLine logLevel httpLogCtx
 
-computeTimeDiff :: Maybe (UTCTime, UTCTime) -> Maybe Double
-computeTimeDiff = fmap (realToFrac . uncurry (flip diffUTCTime))
-
 getSourceFromSocket :: Wai.Request -> ByteString
 getSourceFromSocket = BS.pack . showSockAddr . Wai.remoteHost