add json rpc timings to info logs based on flag json-rpc-log-timings

command/server/config/config.go

@@ -30,6 +30,7 @@ type Config struct {
 	LogFilePath              string     `json:"log_to" yaml:"log_to"`
 	JSONRPCBatchRequestLimit uint64     `json:"json_rpc_batch_request_limit" yaml:"json_rpc_batch_request_limit"`
 	JSONRPCBlockRangeLimit   uint64     `json:"json_rpc_block_range_limit" yaml:"json_rpc_block_range_limit"`
+	JSONRPCLogTimings        bool       `json:"json_rpc_log_timings" yaml:"json_rpc_log_timings"`
 	JSONLogFormat            bool       `json:"json_log_format" yaml:"json_log_format"`
 	CorsAllowedOrigins       []string   `json:"cors_allowed_origins" yaml:"cors_allowed_origins"`
 
@@ -121,6 +122,7 @@ func DefaultConfig() *Config {
 		LogFilePath:              "",
 		JSONRPCBatchRequestLimit: DefaultJSONRPCBatchRequestLimit,
 		JSONRPCBlockRangeLimit:   DefaultJSONRPCBlockRangeLimit,
+		JSONRPCLogTimings:        false,
 		Relayer:                  false,
 		NumBlockConfirmations:    DefaultNumBlockConfirmations,
 	}

command/server/params.go

@@ -30,6 +30,7 @@ const (
 	priceLimitFlag               = "price-limit"
 	jsonRPCBatchRequestLimitFlag = "json-rpc-batch-request-limit"
 	jsonRPCBlockRangeLimitFlag   = "json-rpc-block-range-limit"
+	jsonRPCLogTimingsFlag        = "json-rpc-log-timings"
 	maxSlotsFlag                 = "max-slots"
 	maxEnqueuedFlag              = "max-enqueued"
 	blockGasTargetFlag           = "block-gas-target"
@@ -155,6 +156,7 @@ func (p *serverParams) generateConfig() *server.Config {
 			AccessControlAllowOrigin: p.rawConfig.CorsAllowedOrigins,
 			BatchLengthLimit:         p.rawConfig.JSONRPCBatchRequestLimit,
 			BlockRangeLimit:          p.rawConfig.JSONRPCBlockRangeLimit,
+			LogTimings:               p.rawConfig.JSONRPCLogTimings,
 		},
 		GRPCAddr:   p.grpcAddress,
 		LibP2PAddr: p.libp2pAddress,

command/server/server.go

@@ -215,6 +215,13 @@ func setFlags(cmd *cobra.Command) {
 			"that consider fromBlock/toBlock values (e.g. eth_getLogs), value of 0 disables it",
 	)
 
+	cmd.Flags().BoolVar(
+		&params.rawConfig.JSONRPCLogTimings,
+		jsonRPCLogTimingsFlag,
+		defaultConfig.JSONRPCLogTimings,
+		"enable logging of json-rpc request timings at INFO level",
+	)
+
 	cmd.Flags().StringVar(
 		&params.rawConfig.LogFilePath,
 		logFileLocationFlag,

jsonrpc/dispatcher.go

@@ -347,7 +347,7 @@ func (d *Dispatcher) handleSingleWs(req Request, conn wsConn) Response {
 	return NewRPCResponse(id, "2.0", response, err)
 }
 
-func (d *Dispatcher) Handle(reqBody []byte) ([]byte, error) {
+func (d *Dispatcher) Handle(reqBody []byte, timings *timings) ([]byte, error) {
 	x := bytes.TrimLeft(reqBody, " \t\r\n")
 	if len(x) == 0 {
 		return NewRPCResponse(nil, "2.0", nil, NewInvalidRequestError("Invalid json request")).Bytes()
@@ -363,7 +363,13 @@ func (d *Dispatcher) Handle(reqBody []byte) ([]byte, error) {
 			return NewRPCResponse(req.ID, "2.0", nil, NewInvalidRequestError("Invalid json request")).Bytes()
 		}
 
+		now := time.Now()
 		resp, err := d.handleReq(req)
+		taken := time.Since(now)
+		timings.Timings = append(timings.Timings, timing{
+			Method:   req.Method,
+			Duration: taken,
+		})
 
 		return NewRPCResponse(req.ID, "2.0", resp, err).Bytes()
 	}
@@ -391,14 +397,21 @@ func (d *Dispatcher) Handle(reqBody []byte) ([]byte, error) {
 
 	responses := make([]Response, 0)
 
+	var now time.Time
 	for _, req := range requests {
+		now = time.Now()
 		var response, err = d.handleReq(req)
 		if err != nil {
 			errorResponse := NewRPCResponse(req.ID, "2.0", response, err)
 			responses = append(responses, errorResponse)
 
 			continue
 		}
+		taken := time.Since(now)
+		timings.Timings = append(timings.Timings, timing{
+			Method:   req.Method,
+			Duration: taken,
+		})
 
 		resp := NewRPCResponse(req.ID, "2.0", response, nil)
 		responses = append(responses, resp)

jsonrpc/jsonrpc.go

@@ -48,7 +48,7 @@ type JSONRPC struct {
 type dispatcher interface {
 	RemoveFilterByWs(conn wsConn)
 	HandleWs(reqBody []byte, conn wsConn) ([]byte, error)
-	Handle(reqBody []byte) ([]byte, error)
+	Handle(reqBody []byte, timings *timings) ([]byte, error)
 }
 
 // JSONRPCStore defines all the methods required
@@ -72,6 +72,7 @@ type Config struct {
 	BatchLengthLimit         uint64
 	BlockRangeLimit          uint64
 	TxHandoff                string
+	LogTimings               bool
 }
 
 // NewJSONRPC returns the JSONRPC http server
@@ -330,14 +331,23 @@ func (j *JSONRPC) handleJSONRPCRequest(w http.ResponseWriter, req *http.Request)
 	// log request
 	j.logger.Debug("handle", "request", string(data))
 
-	resp, err := j.dispatcher.Handle(data)
+	timings := &timings{}
+	resp, err := j.dispatcher.Handle(data, timings)
 
 	if err != nil {
 		_, _ = w.Write([]byte(err.Error()))
 	} else {
 		_, _ = w.Write(resp)
 	}
 
+	if j.config.LogTimings {
+		t, err := timings.Output()
+		if err != nil {
+			j.logger.Error("handle", "timings", err.Error())
+		} else {
+			j.logger.Info(fmt.Sprintf("call_timings=%s", t))
+		}
+	}
 	j.logger.Debug("handle", "response", string(resp))
 }
 
@@ -363,3 +373,35 @@ func (j *JSONRPC) handleGetRequest(writer io.Writer) {
 		_, _ = writer.Write([]byte(err.Error()))
 	}
 }
+
+type timing struct {
+	Method   string
+	Duration time.Duration
+}
+
+type timings struct {
+	Timings []timing
+}
+
+func (t *timings) Output() (string, error) {
+	type output struct {
+		Method   string `json:"m"`
+		Duration string `json:"d"`
+	}
+
+	res := make([]output, 0, len(t.Timings))
+
+	for _, timing := range t.Timings {
+		res = append(res, output{
+			Method:   timing.Method,
+			Duration: timing.Duration.String(),
+		})
+	}
+
+	asJson, err := jsonit.Marshal(res)
+	if err != nil {
+		return "", err
+	}
+
+	return string(asJson), nil
+}

server/config.go

@@ -58,4 +58,5 @@ type JSONRPC struct {
 	AccessControlAllowOrigin []string
 	BatchLengthLimit         uint64
 	BlockRangeLimit          uint64
+	LogTimings               bool
 }

server/server.go

@@ -104,8 +104,8 @@ type Server struct {
 	isRelayer bool
 
 	// address for where the json RPC should handoff eth_sendRawTransaction requests to
-	txHandoff string
-	txpoolStorage  txpool.Storage
+	txHandoff     string
+	txpoolStorage txpool.Storage
 }
 
 // newFileLogger returns logger instance that writes all logs to a specified file.
@@ -981,6 +981,7 @@ func (s *Server) setupJSONRPC() error {
 		BatchLengthLimit:         s.config.JSONRPC.BatchLengthLimit,
 		BlockRangeLimit:          s.config.JSONRPC.BlockRangeLimit,
 		TxHandoff:                s.txHandoff,
+		LogTimings:               s.config.JSONRPC.LogTimings,
 	}
 
 	srv, err := jsonrpc.NewJSONRPC(s.logger, conf)