github.com/koko1123/flow-go-1@v0.29.6/fvm/environment/program_logger.go (about)

     1  package environment
     2  
     3  import (
     4  	"time"
     5  
     6  	"github.com/onflow/cadence/runtime/common"
     7  	"github.com/rs/zerolog"
     8  	"go.opentelemetry.io/otel/attribute"
     9  	otelTrace "go.opentelemetry.io/otel/trace"
    10  
    11  	"github.com/koko1123/flow-go-1/fvm/tracing"
    12  	"github.com/koko1123/flow-go-1/module/trace"
    13  )
    14  
    15  // MetricsReporter captures and reports metrics to back to the execution
    16  // environment it is a setup passed to the context.
    17  type MetricsReporter interface {
    18  	RuntimeTransactionParsed(time.Duration)
    19  	RuntimeTransactionChecked(time.Duration)
    20  	RuntimeTransactionInterpreted(time.Duration)
    21  	RuntimeSetNumberOfAccounts(count uint64)
    22  }
    23  
    24  // NoopMetricsReporter is a MetricReporter that does nothing.
    25  type NoopMetricsReporter struct{}
    26  
    27  // RuntimeTransactionParsed is a noop
    28  func (NoopMetricsReporter) RuntimeTransactionParsed(time.Duration) {}
    29  
    30  // RuntimeTransactionChecked is a noop
    31  func (NoopMetricsReporter) RuntimeTransactionChecked(time.Duration) {}
    32  
    33  // RuntimeTransactionInterpreted is a noop
    34  func (NoopMetricsReporter) RuntimeTransactionInterpreted(time.Duration) {}
    35  
    36  // RuntimeSetNumberOfAccounts is a noop
    37  func (NoopMetricsReporter) RuntimeSetNumberOfAccounts(count uint64) {}
    38  
    39  type ProgramLoggerParams struct {
    40  	zerolog.Logger
    41  
    42  	CadenceLoggingEnabled bool
    43  
    44  	MetricsReporter
    45  }
    46  
    47  func DefaultProgramLoggerParams() ProgramLoggerParams {
    48  	return ProgramLoggerParams{
    49  		Logger:                zerolog.Nop(),
    50  		CadenceLoggingEnabled: false,
    51  		MetricsReporter:       NoopMetricsReporter{},
    52  	}
    53  }
    54  
    55  type ProgramLogger struct {
    56  	tracer tracing.TracerSpan
    57  
    58  	ProgramLoggerParams
    59  
    60  	logs []string
    61  }
    62  
    63  func NewProgramLogger(
    64  	tracer tracing.TracerSpan,
    65  	params ProgramLoggerParams,
    66  ) *ProgramLogger {
    67  	return &ProgramLogger{
    68  		tracer:              tracer,
    69  		ProgramLoggerParams: params,
    70  		logs:                nil,
    71  	}
    72  }
    73  
    74  func (logger *ProgramLogger) Logger() *zerolog.Logger {
    75  	return &logger.ProgramLoggerParams.Logger
    76  }
    77  
    78  func (logger *ProgramLogger) ImplementationDebugLog(message string) error {
    79  	logger.Logger().Debug().Msgf("Cadence: %s", message)
    80  	return nil
    81  }
    82  
    83  func (logger *ProgramLogger) ProgramLog(message string) error {
    84  	defer logger.tracer.StartExtensiveTracingChildSpan(
    85  		trace.FVMEnvProgramLog).End()
    86  
    87  	if logger.CadenceLoggingEnabled {
    88  		logger.logs = append(logger.logs, message)
    89  	}
    90  	return nil
    91  }
    92  
    93  func (logger *ProgramLogger) Logs() []string {
    94  	return logger.logs
    95  }
    96  
    97  func (logger *ProgramLogger) RecordTrace(
    98  	operation string,
    99  	location common.Location,
   100  	duration time.Duration,
   101  	attrs []attribute.KeyValue,
   102  ) {
   103  	if location != nil {
   104  		attrs = append(attrs, attribute.String("location", location.String()))
   105  	}
   106  
   107  	end := time.Now()
   108  
   109  	span := logger.tracer.StartChildSpan(
   110  		trace.FVMCadenceTrace.Child(operation),
   111  		otelTrace.WithAttributes(attrs...),
   112  		otelTrace.WithTimestamp(end.Add(-duration)))
   113  	span.End(otelTrace.WithTimestamp(end))
   114  }
   115  
   116  // ProgramParsed captures time spent on parsing a code at specific location
   117  func (logger *ProgramLogger) ProgramParsed(
   118  	location common.Location,
   119  	duration time.Duration,
   120  ) {
   121  	logger.RecordTrace("parseProgram", location, duration, nil)
   122  
   123  	// These checks prevent re-reporting durations, the metrics collection is
   124  	// a bit counter-intuitive:
   125  	// The three functions (parsing, checking, interpretation) are not called
   126  	// in sequence, but in some cases as part of each other. We basically only
   127  	// measure the durations reported for the entry-point (the transaction),
   128  	// and not for child locations, because they might be already part of the
   129  	// duration for the entry-point.
   130  	if location == nil {
   131  		return
   132  	}
   133  	if _, ok := location.(common.TransactionLocation); ok {
   134  		logger.MetricsReporter.RuntimeTransactionParsed(duration)
   135  	}
   136  }
   137  
   138  // ProgramChecked captures time spent on checking a code at specific location
   139  func (logger *ProgramLogger) ProgramChecked(
   140  	location common.Location,
   141  	duration time.Duration,
   142  ) {
   143  	logger.RecordTrace("checkProgram", location, duration, nil)
   144  
   145  	// see the comment for ProgramParsed
   146  	if location == nil {
   147  		return
   148  	}
   149  	if _, ok := location.(common.TransactionLocation); ok {
   150  		logger.MetricsReporter.RuntimeTransactionChecked(duration)
   151  	}
   152  }
   153  
   154  // ProgramInterpreted captures time spent on interpreting a code at specific location
   155  func (logger *ProgramLogger) ProgramInterpreted(
   156  	location common.Location,
   157  	duration time.Duration,
   158  ) {
   159  	logger.RecordTrace("interpretProgram", location, duration, nil)
   160  
   161  	// see the comment for ProgramInterpreted
   162  	if location == nil {
   163  		return
   164  	}
   165  	if _, ok := location.(common.TransactionLocation); ok {
   166  		logger.MetricsReporter.RuntimeTransactionInterpreted(duration)
   167  	}
   168  }
   169  
   170  // ValueEncoded accumulates time spend on runtime value encoding
   171  func (logger *ProgramLogger) ValueEncoded(duration time.Duration) {
   172  	logger.RecordTrace("encodeValue", nil, duration, nil)
   173  }
   174  
   175  // ValueDecoded accumulates time spend on runtime value decoding
   176  func (logger *ProgramLogger) ValueDecoded(duration time.Duration) {
   177  	logger.RecordTrace("decodeValue", nil, duration, nil)
   178  }