log: avoid stack lookups when not needed/used

common/types.go

@@ -25,6 +25,7 @@ import (
 	"math/big"
 	"math/rand"
 	"reflect"
+	"strconv"
 	"strings"
 
 	"github.com/CortexFoundation/CortexTheseus/common/hexutil"
@@ -424,3 +425,35 @@ func Car(data interface{}, err error) interface{} {
 	}
 	return data
 }
+
+// AddressEIP55 is an alias of Address with a customized json marshaller
+type AddressEIP55 Address
+
+// String returns the hex representation of the address in the manner of EIP55.
+func (addr AddressEIP55) String() string {
+	return Address(addr).Hex()
+}
+
+// MarshalJSON marshals the address in the manner of EIP55.
+func (addr AddressEIP55) MarshalJSON() ([]byte, error) {
+	return json.Marshal(addr.String())
+}
+
+type Decimal uint64
+
+func isString(input []byte) bool {
+	return len(input) >= 2 && input[0] == '"' && input[len(input)-1] == '"'
+}
+
+// UnmarshalJSON parses a hash in hex syntax.
+func (d *Decimal) UnmarshalJSON(input []byte) error {
+	if !isString(input) {
+		return &json.UnmarshalTypeError{Value: "non-string", Type: reflect.TypeOf(uint64(0))}
+	}
+	if i, err := strconv.ParseInt(string(input[1:len(input)-1]), 10, 64); err == nil {
+		*d = Decimal(i)
+		return nil
+	} else {
+		return err
+	}
+}

common/types_test.go

@@ -25,6 +25,7 @@ import (
 	"reflect"
 	"strings"
 	"testing"
+	"time"
 )
 
 func TestBytesConversion(t *testing.T) {
@@ -562,3 +563,38 @@ func TestHash_Format(t *testing.T) {
 		})
 	}
 }
+
+func TestAddressEIP55(t *testing.T) {
+	addr := HexToAddress("0x5aaeb6053f3e94c9b9a09f33669435e7ef1beaed")
+	addrEIP55 := AddressEIP55(addr)
+
+	if addr.Hex() != addrEIP55.String() {
+		t.Fatal("AddressEIP55 should match original address hex")
+	}
+
+	blob, err := addrEIP55.MarshalJSON()
+	if err != nil {
+		t.Fatal("Failed to marshal AddressEIP55", err)
+	}
+	if strings.Trim(string(blob), "\"") != addr.Hex() {
+		t.Fatal("Address with checksum is expected")
+	}
+	var dec Address
+	if err := json.Unmarshal(blob, &dec); err != nil {
+		t.Fatal("Failed to unmarshal AddressEIP55", err)
+	}
+	if addr != dec {
+		t.Fatal("Unexpected address after unmarshal")
+	}
+}
+
+func BenchmarkPrettyDuration(b *testing.B) {
+	var x = PrettyDuration(time.Duration(int64(1203123912312)))
+	b.Logf("Pre %s", time.Duration(x).String())
+	var a string
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		a = x.String()
+	}
+	b.Logf("Post %s", a)
+}

log/format.go

@@ -33,8 +33,16 @@ var locationTrims = []string{
 // format output.
 func PrintOrigins(print bool) {
 	locationEnabled.Store(print)
+	if print {
+		stackEnabled.Store(true)
+	}
 }
 
+// stackEnabled is an atomic flag controlling whether the log handler needs
+// to store the callsite stack. This is needed in case any handler wants to
+// print locations (locationEnabled), use vmodule, or print full stacks (BacktraceAt).
+var stackEnabled atomic.Bool
+
 // locationEnabled is an atomic flag controlling whether the terminal formatter
 // should append the log locations too when printing entries.
 var locationEnabled atomic.Bool

log/handler_glog.go

@@ -139,7 +139,10 @@ func (h *GlogHandler) Vmodule(ruleset string) error {
 	h.patterns = filter
 	h.siteCache = make(map[uintptr]Lvl)
 	h.override.Store(len(filter) != 0)
-
+	// Enable location storage (globally)
+	if len(h.patterns) > 0 {
+		stackEnabled.Store(true)
+	}
 	return nil
 }
 
@@ -172,7 +175,8 @@ func (h *GlogHandler) BacktraceAt(location string) error {
 
 	h.location = location
 	h.backtrace.Store(len(location) > 0)
-
+	// Enable location storage (globally)
+	stackEnabled.Store(true)
 	return nil
 }
 

log/logger.go

@@ -177,19 +177,22 @@ type logger struct {
 }
 
 func (l *logger) write(msg string, lvl Lvl, ctx []interface{}, skip int) {
-	l.h.Log(&Record{
+	record := &Record{
 		Time: time.Now(),
 		Lvl:  lvl,
 		Msg:  msg,
 		Ctx:  newContext(l.ctx, ctx),
-		Call: stack.Caller(skip),
 		KeyNames: RecordKeyNames{
 			Time: timeKey,
 			Msg:  msgKey,
 			Lvl:  lvlKey,
 			Ctx:  ctxKey,
 		},
-	})
+	}
+	if stackEnabled.Load() {
+		record.Call = stack.Caller(skip)
+	}
+	l.h.Log(record)
 }
 
 func (l *logger) New(ctx ...interface{}) Logger {

log/logger_test.go

@@ -0,0 +1,67 @@
+package log
+
+import (
+	"bytes"
+	"os"
+	"strings"
+	"testing"
+)
+
+// TestLoggingWithTrace checks that if BackTraceAt is set, then the
+// gloghandler is capable of spitting out a stacktrace
+func TestLoggingWithTrace(t *testing.T) {
+	defer stackEnabled.Store(stackEnabled.Load())
+	out := new(bytes.Buffer)
+	logger := New()
+	{
+		glog := NewGlogHandler(StreamHandler(out, TerminalFormat(false)))
+		glog.Verbosity(LvlTrace)
+		if err := glog.BacktraceAt("logger_test.go:24"); err != nil {
+			t.Fatal(err)
+		}
+		logger.SetHandler(glog)
+	}
+	logger.Trace("a message", "foo", "bar") // Will be bumped to INFO
+	have := out.String()
+	if !strings.HasPrefix(have, "INFO") {
+		t.Fatalf("backtraceat should bump level to info: %s", have)
+	}
+	// The timestamp is locale-dependent, so we want to trim that off
+	// "INFO [01-01|00:00:00.000] a messag ..." -> "a messag..."
+	have = strings.Split(have, "]")[1]
+	wantPrefix := " a message\n\ngoroutine"
+	if !strings.HasPrefix(have, wantPrefix) {
+		t.Errorf("\nhave: %q\nwant: %q\n", have, wantPrefix)
+	}
+}
+
+// TestLoggingWithVmodule checks that vmodule works.
+func TestLoggingWithVmodule(t *testing.T) {
+	defer stackEnabled.Store(stackEnabled.Load())
+	out := new(bytes.Buffer)
+	logger := New()
+	{
+		glog := NewGlogHandler(StreamHandler(out, TerminalFormat(false)))
+		glog.Verbosity(LvlCrit)
+		logger.SetHandler(glog)
+		logger.Warn("This should not be seen", "ignored", "true")
+		glog.Vmodule("logger_test.go=5")
+	}
+	logger.Trace("a message", "foo", "bar")
+	have := out.String()
+	// The timestamp is locale-dependent, so we want to trim that off
+	// "INFO [01-01|00:00:00.000] a messag ..." -> "a messag..."
+	have = strings.Split(have, "]")[1]
+	want := " a message                                foo=bar\n"
+	if have != want {
+		t.Errorf("\nhave: %q\nwant: %q\n", have, want)
+	}
+}
+
+func BenchmarkTraceLogging(b *testing.B) {
+	Root().SetHandler(LvlFilterHandler(LvlInfo, StreamHandler(os.Stderr, TerminalFormat(true))))
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		Trace("a message", "v", i)
+	}
+}