[performance] more logging tweaks (#4415)

- reduces number of necessary function calls by moving log level checking out of the uninlineable `logf(...)` function and into each of its caller (which are all inlined). this in turn means the log level check is performed in-situ wherever a call to `log.Debug(...)` (etc) is made, reduce unnecessary calls when a certain log level is disabled.
- sets the http.Server{}.ErrorLog to output to our internal logging package (which in turn ensures it gets wrapped in either our logfmt or json log formatting)

Reviewed-on: https://codeberg.org/superseriousbusiness/gotosocial/pulls/4415
Co-authored-by: kim <grufwub@gmail.com>
Co-committed-by: kim <grufwub@gmail.com>
This commit is contained in:
kim 2025-09-07 14:47:45 +02:00 committed by kim
commit 19784e381b
5 changed files with 263 additions and 7 deletions

View file

@ -49,51 +49,81 @@ func (e Entry) WithFields(kvs ...kv.Field) Entry {
// Trace will log formatted args as 'msg' field to the log at TRACE level.
func (e Entry) Trace(a ...interface{}) {
if TRACE > loglvl {
return
}
logf(e.ctx, TRACE, e.kvs, "", a...)
}
// Tracef will log format string as 'msg' field to the log at TRACE level.
func (e Entry) Tracef(s string, a ...interface{}) {
if TRACE > loglvl {
return
}
logf(e.ctx, TRACE, e.kvs, s, a...)
}
// Debug will log formatted args as 'msg' field to the log at DEBUG level.
func (e Entry) Debug(a ...interface{}) {
if DEBUG > loglvl {
return
}
logf(e.ctx, DEBUG, e.kvs, "", a...)
}
// Debugf will log format string as 'msg' field to the log at DEBUG level.
func (e Entry) Debugf(s string, a ...interface{}) {
if DEBUG > loglvl {
return
}
logf(e.ctx, DEBUG, e.kvs, s, a...)
}
// Info will log formatted args as 'msg' field to the log at INFO level.
func (e Entry) Info(a ...interface{}) {
if INFO > loglvl {
return
}
logf(e.ctx, INFO, e.kvs, "", a...)
}
// Infof will log format string as 'msg' field to the log at INFO level.
func (e Entry) Infof(s string, a ...interface{}) {
if INFO > loglvl {
return
}
logf(e.ctx, INFO, e.kvs, s, a...)
}
// Warn will log formatted args as 'msg' field to the log at WARN level.
func (e Entry) Warn(a ...interface{}) {
if WARN > loglvl {
return
}
logf(e.ctx, WARN, e.kvs, "", a...)
}
// Warnf will log format string as 'msg' field to the log at WARN level.
func (e Entry) Warnf(s string, a ...interface{}) {
if WARN > loglvl {
return
}
logf(e.ctx, WARN, e.kvs, s, a...)
}
// Error will log formatted args as 'msg' field to the log at ERROR level.
func (e Entry) Error(a ...interface{}) {
if ERROR > loglvl {
return
}
logf(e.ctx, ERROR, e.kvs, "", a...)
}
// Errorf will log format string as 'msg' field to the log at ERROR level.
func (e Entry) Errorf(s string, a ...interface{}) {
if ERROR > loglvl {
return
}
logf(e.ctx, ERROR, e.kvs, s, a...)
}
@ -101,6 +131,9 @@ func (e Entry) Errorf(s string, a ...interface{}) {
// This will then call panic causing the application to crash.
func (e Entry) Panic(a ...interface{}) {
defer panic(fmt.Sprint(a...))
if PANIC > loglvl {
return
}
logf(e.ctx, PANIC, e.kvs, "", a...)
}
@ -108,16 +141,25 @@ func (e Entry) Panic(a ...interface{}) {
// This will then call panic causing the application to crash.
func (e Entry) Panicf(s string, a ...interface{}) {
defer panic(fmt.Sprintf(s, a...))
if PANIC > loglvl {
return
}
logf(e.ctx, PANIC, e.kvs, s, a...)
}
// Log will log formatted args as 'msg' field to the log at given level.
func (e Entry) Log(lvl LEVEL, a ...interface{}) {
if lvl > loglvl {
return
}
logf(e.ctx, lvl, e.kvs, "", a...)
}
// Logf will log format string as 'msg' field to the log at given level.
func (e Entry) Logf(lvl LEVEL, s string, a ...interface{}) {
if lvl > loglvl {
return
}
logf(e.ctx, lvl, e.kvs, s, a...)
}

View file

@ -112,101 +112,161 @@ func WithFields(fields ...kv.Field) Entry {
// Trace will log formatted args as 'msg' field to the log at TRACE level.
func Trace(ctx context.Context, a ...interface{}) {
if TRACE > loglvl {
return
}
logf(ctx, TRACE, nil, "", a...)
}
// Tracef will log format string as 'msg' field to the log at TRACE level.
func Tracef(ctx context.Context, s string, a ...interface{}) {
if TRACE > loglvl {
return
}
logf(ctx, TRACE, nil, s, a...)
}
// TraceKV will log the one key-value field to the log at TRACE level.
func TraceKV(ctx context.Context, key string, value interface{}) {
if TRACE > loglvl {
return
}
logf(ctx, TRACE, []kv.Field{{K: key, V: value}}, "")
}
// TraceKVs will log key-value fields to the log at TRACE level.
func TraceKVs(ctx context.Context, kvs ...kv.Field) {
if TRACE > loglvl {
return
}
logf(ctx, TRACE, kvs, "")
}
// Debug will log formatted args as 'msg' field to the log at DEBUG level.
func Debug(ctx context.Context, a ...interface{}) {
if DEBUG > loglvl {
return
}
logf(ctx, DEBUG, nil, "", a...)
}
// Debugf will log format string as 'msg' field to the log at DEBUG level.
func Debugf(ctx context.Context, s string, a ...interface{}) {
if DEBUG > loglvl {
return
}
logf(ctx, DEBUG, nil, s, a...)
}
// DebugKV will log the one key-value field to the log at DEBUG level.
func DebugKV(ctx context.Context, key string, value interface{}) {
if DEBUG > loglvl {
return
}
logf(ctx, DEBUG, []kv.Field{{K: key, V: value}}, "")
}
// DebugKVs will log key-value fields to the log at DEBUG level.
func DebugKVs(ctx context.Context, kvs ...kv.Field) {
if DEBUG > loglvl {
return
}
logf(ctx, DEBUG, kvs, "")
}
// Info will log formatted args as 'msg' field to the log at INFO level.
func Info(ctx context.Context, a ...interface{}) {
if INFO > loglvl {
return
}
logf(ctx, INFO, nil, "", a...)
}
// Infof will log format string as 'msg' field to the log at INFO level.
func Infof(ctx context.Context, s string, a ...interface{}) {
if INFO > loglvl {
return
}
logf(ctx, INFO, nil, s, a...)
}
// InfoKV will log the one key-value field to the log at INFO level.
func InfoKV(ctx context.Context, key string, value interface{}) {
if INFO > loglvl {
return
}
logf(ctx, INFO, []kv.Field{{K: key, V: value}}, "")
}
// InfoKVs will log key-value fields to the log at INFO level.
func InfoKVs(ctx context.Context, kvs ...kv.Field) {
if INFO > loglvl {
return
}
logf(ctx, INFO, kvs, "")
}
// Warn will log formatted args as 'msg' field to the log at WARN level.
func Warn(ctx context.Context, a ...interface{}) {
if WARN > loglvl {
return
}
logf(ctx, WARN, nil, "", a...)
}
// Warnf will log format string as 'msg' field to the log at WARN level.
func Warnf(ctx context.Context, s string, a ...interface{}) {
if WARN > loglvl {
return
}
logf(ctx, WARN, nil, s, a...)
}
// WarnKV will log the one key-value field to the log at WARN level.
func WarnKV(ctx context.Context, key string, value interface{}) {
if WARN > loglvl {
return
}
logf(ctx, WARN, []kv.Field{{K: key, V: value}}, "")
}
// WarnKVs will log key-value fields to the log at WARN level.
func WarnKVs(ctx context.Context, kvs ...kv.Field) {
if WARN > loglvl {
return
}
logf(ctx, WARN, kvs, "")
}
// Error will log formatted args as 'msg' field to the log at ERROR level.
func Error(ctx context.Context, a ...interface{}) {
if ERROR > loglvl {
return
}
logf(ctx, ERROR, nil, "", a...)
}
// Errorf will log format string as 'msg' field to the log at ERROR level.
func Errorf(ctx context.Context, s string, a ...interface{}) {
if ERROR > loglvl {
return
}
logf(ctx, ERROR, nil, s, a...)
}
// ErrorKV will log the one key-value field to the log at ERROR level.
func ErrorKV(ctx context.Context, key string, value interface{}) {
if ERROR > loglvl {
return
}
logf(ctx, ERROR, []kv.Field{{K: key, V: value}}, "")
}
// ErrorKVs will log key-value fields to the log at ERROR level.
func ErrorKVs(ctx context.Context, kvs ...kv.Field) {
if ERROR > loglvl {
return
}
logf(ctx, ERROR, kvs, "")
}
@ -214,6 +274,9 @@ func ErrorKVs(ctx context.Context, kvs ...kv.Field) {
// This will then call panic causing the application to crash.
func Panic(ctx context.Context, a ...interface{}) {
defer panic(fmt.Sprint(a...))
if PANIC > loglvl {
return
}
logf(ctx, PANIC, nil, "", a...)
}
@ -221,6 +284,9 @@ func Panic(ctx context.Context, a ...interface{}) {
// This will then call panic causing the application to crash.
func Panicf(ctx context.Context, s string, a ...interface{}) {
defer panic(fmt.Sprintf(s, a...))
if PANIC > loglvl {
return
}
logf(ctx, PANIC, nil, s, a...)
}
@ -228,6 +294,9 @@ func Panicf(ctx context.Context, s string, a ...interface{}) {
// This will then call panic causing the application to crash.
func PanicKV(ctx context.Context, key string, value interface{}) {
defer panic(kv.Field{K: key, V: value}.String())
if PANIC > loglvl {
return
}
logf(ctx, PANIC, []kv.Field{{K: key, V: value}}, "")
}
@ -235,26 +304,41 @@ func PanicKV(ctx context.Context, key string, value interface{}) {
// This will then call panic causing the application to crash.
func PanicKVs(ctx context.Context, kvs ...kv.Field) {
defer panic(kv.Fields(kvs).String())
if PANIC > loglvl {
return
}
logf(ctx, PANIC, kvs, "")
}
// Log will log formatted args as 'msg' field to the log at given level.
func Log(ctx context.Context, lvl LEVEL, a ...interface{}) { //nolint:revive
if lvl > loglvl {
return
}
logf(ctx, lvl, nil, "", a...)
}
// Logf will log format string as 'msg' field to the log at given level.
func Logf(ctx context.Context, lvl LEVEL, s string, a ...interface{}) { //nolint:revive
if lvl > loglvl {
return
}
logf(ctx, lvl, nil, s, a...)
}
// LogKV will log the one key-value field to the log at given level.
func LogKV(ctx context.Context, lvl LEVEL, key string, value interface{}) { //nolint:revive
if lvl > loglvl {
return
}
logf(ctx, lvl, []kv.Field{{K: key, V: value}}, "")
}
// LogKVs will log key-value fields to the log at given level.
func LogKVs(ctx context.Context, lvl LEVEL, kvs ...kv.Field) { //nolint:revive
if lvl > loglvl {
return
}
logf(ctx, lvl, kvs, "")
}
@ -272,11 +356,6 @@ func Printf(s string, a ...interface{}) {
func logf(ctx context.Context, lvl LEVEL, fields []kv.Field, msg string, args ...interface{}) {
var out *os.File
// Check if enabled.
if lvl > loglvl {
return
}
// Split errors to stderr,
// all else goes to stdout.
if lvl <= ERROR {

89
internal/log/log_test.go Normal file
View file

@ -0,0 +1,89 @@
// GoToSocial
// Copyright (C) GoToSocial Authors admin@gotosocial.org
// SPDX-License-Identifier: AGPL-3.0-or-later
//
// This program is free software: you can redistribute it and/or modify
// it under the terms of the GNU Affero General Public License as published by
// the Free Software Foundation, either version 3 of the License, or
// (at your option) any later version.
//
// This program is distributed in the hope that it will be useful,
// but WITHOUT ANY WARRANTY; without even the implied warranty of
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
// GNU Affero General Public License for more details.
//
// You should have received a copy of the GNU Affero General Public License
// along with this program. If not, see <http://www.gnu.org/licenses/>.
package log_test
import (
"testing"
"code.superseriousbusiness.org/gotosocial/internal/log"
"codeberg.org/gruf/go-kv/v2"
)
func TestInlineability(t *testing.T) {
t.Skip()
// to check the output of this run:
// go test -gcflags=all='-m=2' ./internal/log/ -run=TestInlineability 2>&1 | grep 'internal/log/log_test.go.*cannot inline'
//
// the output should not include any
// of the below log package func calls.
ctx := t.Context()
const s = "hello world"
log.Debug(ctx, s)
log.Debugf(ctx, s)
log.DebugKV(ctx, "key", s)
log.DebugKVs(ctx, kv.Fields{{K: "key", V: s}}...)
log.Info(ctx, s)
log.Infof(ctx, s)
log.InfoKV(ctx, "key", s)
log.InfoKVs(ctx, kv.Fields{{K: "key", V: s}}...)
log.Warn(ctx, s)
log.Warnf(ctx, s)
log.WarnKV(ctx, "key", s)
log.WarnKVs(ctx, kv.Fields{{K: "key", V: s}}...)
log.Error(ctx, s)
log.Errorf(ctx, s)
log.ErrorKV(ctx, "key", s)
log.ErrorKVs(ctx, kv.Fields{{K: "key", V: s}}...)
log.Panic(ctx, s)
log.Panicf(ctx, s)
log.PanicKV(ctx, "key", s)
log.PanicKVs(ctx, kv.Fields{{K: "key", V: s}}...)
log.Print(s)
log.Printf(s)
e := log.New()
e = e.WithContext(ctx)
e = e.WithField("key", s)
e = e.WithFields(kv.Fields{{K: "key", V: s}}...)
e.Debug(s)
e.Debugf(s)
e.Info(s)
e.Infof(s)
e.Warn(s)
e.Warnf(s)
e.Error(s)
e.Errorf(s)
e.Panic(s)
e.Panicf(s)
e.Print(s)
e.Printf(s)
}

43
internal/log/std.go Normal file
View file

@ -0,0 +1,43 @@
// GoToSocial
// Copyright (C) GoToSocial Authors admin@gotosocial.org
// SPDX-License-Identifier: AGPL-3.0-or-later
//
// This program is free software: you can redistribute it and/or modify
// it under the terms of the GNU Affero General Public License as published by
// the Free Software Foundation, either version 3 of the License, or
// (at your option) any later version.
//
// This program is distributed in the hope that it will be useful,
// but WITHOUT ANY WARRANTY; without even the implied warranty of
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
// GNU Affero General Public License for more details.
//
// You should have received a copy of the GNU Affero General Public License
// along with this program. If not, see <http://www.gnu.org/licenses/>.
package log
import (
"log"
"codeberg.org/gruf/go-kv/v2"
)
// NewStdLogger returns a new standard library
// log.Logger instance that will write output
// to this library's logging functions at 'lvl'.
func NewStdLogger(lvl LEVEL) *log.Logger {
return log.New(stdLogWriter{lvl: lvl}, "", 0)
}
type stdLogWriter struct{ lvl LEVEL }
func (w stdLogWriter) Write(b []byte) (int, error) {
if w.lvl <= loglvl {
logf(nil, w.lvl, kv.Fields{
{K: "caller", V: Caller(5)},
{K: "msg", V: b},
}, "")
}
return len(b), nil
}

View file

@ -23,6 +23,7 @@ import (
"fmt"
"net"
"net/http"
"strconv"
"time"
"code.superseriousbusiness.org/gotosocial/internal/config"
@ -93,9 +94,10 @@ func New(ctx context.Context) (*Router, error) {
// `server start` command anyway.
baseCtx := func(_ net.Listener) context.Context { return ctx }
addr := fmt.Sprintf("%s:%d",
// Create joined listen addr.
addr := net.JoinHostPort(
config.GetBindAddress(),
config.GetPort(),
strconv.Itoa(config.GetPort()),
)
// Wrap the gin engine handler in our
@ -111,6 +113,7 @@ func New(ctx context.Context) (*Router, error) {
WriteTimeout: writeTimeout,
IdleTimeout: idleTimeout,
BaseContext: baseCtx,
ErrorLog: log.NewStdLogger(log.ERROR),
}
return &Router{