Reduce logging allocations

daemon/log_ring.go

@@ -0,0 +1,39 @@
+package daemon
+
+import (
+	"github.com/sagernet/sing-box/log"
+)
+
+type logRing struct {
+	entries  []*log.Entry
+	maxLines int
+	start    int
+}
+
+func (r *logRing) push(entry *log.Entry) {
+	if r.maxLines <= 0 {
+		return
+	}
+	if len(r.entries) < r.maxLines {
+		r.entries = append(r.entries, entry)
+		return
+	}
+	r.entries[r.start] = entry
+	r.start++
+	if r.start == len(r.entries) {
+		r.start = 0
+	}
+}
+
+func (r *logRing) array() []*log.Entry {
+	result := make([]*log.Entry, 0, len(r.entries))
+	result = append(result, r.entries[r.start:]...)
+	result = append(result, r.entries[:r.start]...)
+	return result
+}
+
+func (r *logRing) reset() {
+	clear(r.entries)
+	r.entries = r.entries[:0]
+	r.start = 0
+}

daemon/started_service.go

@@ -23,7 +23,6 @@ import (
 	"github.com/sagernet/sing/common"
 	"github.com/sagernet/sing/common/memory"
 	"github.com/sagernet/sing/common/observable"
-	"github.com/sagernet/sing/common/x/list"
 	"github.com/sagernet/sing/service"
 
 	"github.com/gofrs/uuid/v5"
@@ -47,7 +46,6 @@ type StartedService struct {
 	// platform adapter.PlatformInterface
 	handler           PlatformHandler
 	debug             bool
-	logMaxLines       int
 	oomKillerEnabled  bool
 	oomKillerDisabled bool
 	oomMemoryLimit    uint64
@@ -64,7 +62,7 @@ type StartedService struct {
 	serviceStatusSubscriber *observable.Subscriber[*ServiceStatus]
 	serviceStatusObserver   *observable.Observer[*ServiceStatus]
 	logAccess               sync.RWMutex
-	logLines                list.List[*log.Entry]
+	logLines                logRing
 	logSubscriber           *observable.Subscriber[*log.Entry]
 	logObserver             *observable.Observer[*log.Entry]
 	instance                *Instance
@@ -99,7 +97,7 @@ func NewStartedService(options ServiceOptions) *StartedService {
 		// platform:                options.Platform,
 		handler:           options.Handler,
 		debug:             options.Debug,
-		logMaxLines:       options.LogMaxLines,
+		logLines:          logRing{maxLines: options.LogMaxLines},
 		oomKillerEnabled:  options.OOMKillerEnabled,
 		oomKillerDisabled: options.OOMKillerDisabled,
 		oomMemoryLimit:    options.OOMMemoryLimit,
@@ -140,7 +138,7 @@ func (s *StartedService) GetVersion(ctx context.Context, empty *emptypb.Empty) (
 
 func (s *StartedService) resetLogs() {
 	s.logAccess.Lock()
-	s.logLines = list.List[*log.Entry]{}
+	s.logLines.reset()
 	s.logAccess.Unlock()
 	s.logSubscriber.Emit(nil)
 }
@@ -378,12 +376,8 @@ func (s *StartedService) SubscribeServiceStatus(empty *emptypb.Empty, server grp
 }
 
 func (s *StartedService) SubscribeLog(empty *emptypb.Empty, server grpc.ServerStreamingServer[Log]) error {
-	var savedLines []*log.Entry
 	s.logAccess.Lock()
-	savedLines = make([]*log.Entry, 0, s.logLines.Len())
-	for element := s.logLines.Front(); element != nil; element = element.Next() {
-		savedLines = append(savedLines, element.Value)
-	}
+	savedLines := s.logLines.array()
 	subscription, done, err := s.logObserver.Subscribe()
 	s.logAccess.Unlock()
 	if err != nil {
@@ -2092,10 +2086,7 @@ func (s *StartedService) mustEmbedUnimplementedStartedServiceServer() {
 func (s *StartedService) WriteMessage(level log.Level, message string) {
 	item := &log.Entry{Level: level, Message: message}
 	s.logAccess.Lock()
-	s.logLines.PushBack(item)
-	if s.logLines.Len() > s.logMaxLines {
-		s.logLines.Remove(s.logLines.Front())
-	}
+	s.logLines.push(item)
 	s.logAccess.Unlock()
 	s.logSubscriber.Emit(item)
 	if s.debug {
@@ -2106,7 +2097,7 @@ func (s *StartedService) WriteMessage(level log.Level, message string) {
 func (s *StartedService) SavedLog() []*log.Entry {
 	s.logAccess.RLock()
 	defer s.logAccess.RUnlock()
-	return s.logLines.Array()
+	return s.logLines.array()
 }
 
 func (s *StartedService) Instance() *Instance {

log/format.go

@@ -6,8 +6,6 @@ import (
 	"strings"
 	"time"
 
-	F "github.com/sagernet/sing/common/format"
-
 	"github.com/logrusorgru/aurora"
 )
 
@@ -20,155 +18,171 @@ type Formatter struct {
 	DisableLineBreak bool
 }
 
-func (f Formatter) Format(ctx context.Context, level Level, tag string, message string, timestamp time.Time) string {
-	levelString := strings.ToUpper(FormatLevel(level))
-	if !f.DisableColors {
+var (
+	levelLabels        [LevelTrace + 1]string
+	coloredLevelLabels [LevelTrace + 1]string
+)
+
+func init() {
+	for level := LevelPanic; level <= LevelTrace; level++ {
+		label := strings.ToUpper(FormatLevel(level))
+		levelLabels[level] = label
 		switch level {
 		case LevelDebug, LevelTrace:
-			levelString = aurora.White(levelString).String()
+			coloredLevelLabels[level] = aurora.White(label).String()
 		case LevelInfo:
-			levelString = aurora.Cyan(levelString).String()
+			coloredLevelLabels[level] = aurora.Cyan(label).String()
 		case LevelWarn:
-			levelString = aurora.Yellow(levelString).String()
+			coloredLevelLabels[level] = aurora.Yellow(label).String()
 		case LevelError, LevelFatal, LevelPanic:
-			levelString = aurora.Red(levelString).String()
+			coloredLevelLabels[level] = aurora.Red(label).String()
 		}
 	}
-	if tag != "" {
-		message = tag + ": " + message
-	}
+}
+
+func (f Formatter) Format(ctx context.Context, level Level, tag string, message string, timestamp time.Time) string {
 	var id ID
 	var hasId bool
 	if ctx != nil {
 		id, hasId = IDFromContext(ctx)
 	}
+	var builder strings.Builder
+	builder.Grow(len(tag) + len(message) + 64)
+	f.writePrefix(&builder, level, timestamp)
 	if hasId {
-		activeDuration := FormatDuration(time.Since(id.CreatedAt))
-		if !f.DisableColors {
-			var color aurora.Color
-			color = aurora.Color(uint8(id.ID))
-			color %= 215
-			row := uint(color / 36)
-			column := uint(color % 36)
-
-			var r, g, b float32
-			r = float32(row * 51)
-			g = float32(column / 6 * 51)
-			b = float32((column % 6) * 51)
-			luma := 0.2126*r + 0.7152*g + 0.0722*b
-			if luma < 60 {
-				row = 5 - row
-				column = 35 - column
-				color = aurora.Color(row*36 + column)
-			}
-			color += 16
-			color = color << 16
-			color |= 1 << 14
-			message = F.ToString("[", aurora.Colorize(id.ID, color).String(), " ", activeDuration, "] ", message)
-		} else {
-			message = F.ToString("[", id.ID, " ", activeDuration, "] ", message)
-		}
+		f.writeIdPrefix(&builder, id)
 	}
-	switch {
-	case f.DisableTimestamp:
-		message = levelString + " " + message
-	case f.FullTimestamp:
-		message = timestamp.Format(f.TimestampFormat) + " " + levelString + " " + message
-	default:
-		message = levelString + "[" + xd(int(timestamp.Sub(f.BaseTime)/time.Second), 4) + "] " + message
+	if tag != "" {
+		builder.WriteString(tag)
+		builder.WriteString(": ")
 	}
 	if f.DisableLineBreak {
-		if message[len(message)-1] == '\n' {
-			message = message[:len(message)-1]
-		}
+		builder.WriteString(strings.TrimSuffix(message, "\n"))
 	} else {
-		if message[len(message)-1] != '\n' {
-			message += "\n"
+		builder.WriteString(message)
+		if !strings.HasSuffix(message, "\n") {
+			builder.WriteByte('\n')
 		}
 	}
-	return message
+	return builder.String()
 }
 
-func (f Formatter) FormatWithSimple(ctx context.Context, level Level, tag string, message string, timestamp time.Time) (string, string) {
-	levelString := strings.ToUpper(FormatLevel(level))
-	if !f.DisableColors {
-		switch level {
-		case LevelDebug, LevelTrace:
-			levelString = aurora.White(levelString).String()
-		case LevelInfo:
-			levelString = aurora.Cyan(levelString).String()
-		case LevelWarn:
-			levelString = aurora.Yellow(levelString).String()
-		case LevelError, LevelFatal, LevelPanic:
-			levelString = aurora.Red(levelString).String()
-		}
-	}
-	if tag != "" {
-		message = tag + ": " + message
-	}
-	messageSimple := message
+func (f Formatter) FormatSimple(ctx context.Context, tag string, message string) string {
 	var id ID
 	var hasId bool
 	if ctx != nil {
 		id, hasId = IDFromContext(ctx)
 	}
+	if !hasId && tag == "" {
+		return message
+	}
+	var builder strings.Builder
+	builder.Grow(len(tag) + len(message) + 32)
 	if hasId {
-		activeDuration := FormatDuration(time.Since(id.CreatedAt))
-		if !f.DisableColors {
-			var color aurora.Color
-			color = aurora.Color(uint8(id.ID))
-			color %= 215
-			row := uint(color / 36)
-			column := uint(color % 36)
-
-			var r, g, b float32
-			r = float32(row * 51)
-			g = float32(column / 6 * 51)
-			b = float32((column % 6) * 51)
-			luma := 0.2126*r + 0.7152*g + 0.0722*b
-			if luma < 60 {
-				row = 5 - row
-				column = 35 - column
-				color = aurora.Color(row*36 + column)
-			}
-			color += 16
-			color = color << 16
-			color |= 1 << 14
-			message = F.ToString("[", aurora.Colorize(id.ID, color).String(), " ", activeDuration, "] ", message)
-		} else {
-			message = F.ToString("[", id.ID, " ", activeDuration, "] ", message)
-		}
-		messageSimple = F.ToString("[", id.ID, " ", activeDuration, "] ", messageSimple)
+		builder.WriteByte('[')
+		writeUint(&builder, uint64(id.ID))
+		builder.WriteByte(' ')
+		writeDuration(&builder, time.Since(id.CreatedAt))
+		builder.WriteString("] ")
+	}
+	if tag != "" {
+		builder.WriteString(tag)
+		builder.WriteString(": ")
+	}
+	builder.WriteString(message)
+	return builder.String()
+}
 
+func (f Formatter) writePrefix(builder *strings.Builder, level Level, timestamp time.Time) {
+	var levelString string
+	if int(level) >= len(levelLabels) {
+		levelString = "UNKNOWN"
+	} else if f.DisableColors {
+		levelString = levelLabels[level]
+	} else {
+		levelString = coloredLevelLabels[level]
 	}
 	switch {
 	case f.DisableTimestamp:
-		message = levelString + " " + message
+		builder.WriteString(levelString)
+		builder.WriteByte(' ')
 	case f.FullTimestamp:
-		message = timestamp.Format(f.TimestampFormat) + " " + levelString + " " + message
+		var timeBuffer [64]byte
+		builder.Write(timestamp.AppendFormat(timeBuffer[:0], f.TimestampFormat))
+		builder.WriteByte(' ')
+		builder.WriteString(levelString)
+		builder.WriteByte(' ')
 	default:
-		message = levelString + "[" + xd(int(timestamp.Sub(f.BaseTime)/time.Second), 4) + "] " + message
+		builder.WriteString(levelString)
+		builder.WriteByte('[')
+		seconds := strconv.AppendInt(make([]byte, 0, 20), int64(timestamp.Sub(f.BaseTime)/time.Second), 10)
+		for pad := 4 - len(seconds); pad > 0; pad-- {
+			builder.WriteByte('0')
+		}
+		builder.Write(seconds)
+		builder.WriteString("] ")
 	}
-	if message[len(message)-1] != '\n' {
-		message += "\n"
-	}
-	return message, messageSimple
 }
 
-func xd(value int, x int) string {
-	message := strconv.Itoa(value)
-	for len(message) < x {
-		message = "0" + message
+func (f Formatter) writeIdPrefix(builder *strings.Builder, id ID) {
+	builder.WriteByte('[')
+	if f.DisableColors {
+		writeUint(builder, uint64(id.ID))
+	} else {
+		builder.WriteString("\x1b[38;5;")
+		writeUint(builder, uint64(colorForID(id.ID)))
+		builder.WriteByte('m')
+		writeUint(builder, uint64(id.ID))
+		builder.WriteString("\x1b[0m")
+	}
+	builder.WriteByte(' ')
+	writeDuration(builder, time.Since(id.CreatedAt))
+	builder.WriteString("] ")
+}
+
+func colorForID(value uint32) uint8 {
+	color := uint8(value) % 215
+	row := uint(color / 36)
+	column := uint(color % 36)
+	r := float32(row * 51)
+	g := float32(column / 6 * 51)
+	b := float32((column % 6) * 51)
+	luma := 0.2126*r + 0.7152*g + 0.0722*b
+	if luma < 60 {
+		row = 5 - row
+		column = 35 - column
+		color = uint8(row*36 + column)
+	}
+	return color + 16
+}
+
+func writeUint(builder *strings.Builder, value uint64) {
+	builder.Write(strconv.AppendUint(make([]byte, 0, 20), value, 10))
+}
+
+func writeInt(builder *strings.Builder, value int64) {
+	builder.Write(strconv.AppendInt(make([]byte, 0, 20), value, 10))
+}
+
+func writeDuration(builder *strings.Builder, duration time.Duration) {
+	if duration < time.Second {
+		writeInt(builder, duration.Milliseconds())
+		builder.WriteString("ms")
+	} else if duration < time.Minute {
+		writeInt(builder, int64(duration.Seconds()))
+		builder.WriteByte('.')
+		writeInt(builder, int64(duration.Seconds()*100)%100)
+		builder.WriteByte('s')
+	} else {
+		writeInt(builder, int64(duration.Minutes()))
+		builder.WriteByte('m')
+		writeInt(builder, int64(duration.Seconds())%60)
+		builder.WriteByte('s')
 	}
-	return message
 }
 
 func FormatDuration(duration time.Duration) string {
-	if duration < time.Second {
-		return F.ToString(duration.Milliseconds(), "ms")
-	} else if duration < time.Minute {
-		return F.ToString(int64(duration.Seconds()), ".", int64(duration.Seconds()*100)%100, "s")
-	} else {
-		return F.ToString(int64(duration.Minutes()), "m", int64(duration.Seconds())%60, "s")
-	}
+	var builder strings.Builder
+	writeDuration(&builder, duration)
+	return builder.String()
 }

log/observable.go

@@ -24,6 +24,7 @@ type defaultFactory struct {
 	file              *os.File
 	filePath          string
 	platformWriters   atomic.Pointer[[]PlatformWriter]
+	needConsole       bool
 	needObservable    bool
 	level             Level
 	subscriber        *observable.Subscriber[Entry]
@@ -58,6 +59,7 @@ func NewDefaultFactory(
 		},
 		writer:         writer,
 		filePath:       filePath,
+		needConsole:    writer != io.Discard || filePath != "",
 		needObservable: needObservable,
 		level:          LevelTrace,
 		subscriber:     observable.NewSubscriber[Entry](128),
@@ -81,6 +83,7 @@ func (f *defaultFactory) Start() error {
 			f.writer = logFile
 			f.file = logFile
 		}
+		f.needConsole = f.writer != io.Discard
 	}
 	if f.needObservable {
 		f.observer = observable.NewObserver[Entry](f.subscriber, 64)
@@ -144,19 +147,7 @@ func (f *defaultFactory) UnSubscribe(sub observable.Subscription[Entry]) {
 }
 
 func (f *defaultFactory) output(ctx context.Context, level Level, tag string, message string, timestamp time.Time) {
-	if f.needObservable {
-		formatted, formattedSimple := f.formatter.FormatWithSimple(ctx, level, tag, message, timestamp)
-		if level <= f.level {
-			if level == LevelPanic {
-				panic(formatted)
-			}
-			f.writer.Write([]byte(formatted))
-			if level == LevelFatal {
-				os.Exit(1)
-			}
-		}
-		f.subscriber.Emit(Entry{level, formattedSimple})
-	} else if level <= f.level {
+	if level <= f.level && (f.needConsole || level == LevelPanic || level == LevelFatal) {
 		formatted := f.formatter.Format(ctx, level, tag, message, timestamp)
 		if level == LevelPanic {
 			panic(formatted)
@@ -166,6 +157,9 @@ func (f *defaultFactory) output(ctx context.Context, level Level, tag string, me
 			os.Exit(1)
 		}
 	}
+	if f.needObservable {
+		f.subscriber.Emit(Entry{level, f.formatter.FormatSimple(ctx, tag, message)})
+	}
 	platformWriters := f.loadPlatformWriters()
 	if len(platformWriters) > 0 {
 		platformMessage := f.platformFormatter.Format(ctx, level, tag, message, timestamp)