2023-01-27 21:37:20 +00:00
// Copyright (c) Tailscale Inc & AUTHORS
// SPDX-License-Identifier: BSD-3-Clause
2020-02-05 22:16:58 +00:00
package logtail
import (
2022-01-13 22:02:46 +00:00
"bytes"
2020-02-05 22:16:58 +00:00
"context"
2021-01-12 21:31:45 +00:00
"encoding/json"
"io"
2021-01-10 23:03:57 +00:00
"net/http"
"net/http/httptest"
2021-01-12 21:31:45 +00:00
"strings"
2020-02-05 22:16:58 +00:00
"testing"
2020-04-04 21:16:33 +00:00
"time"
2021-10-27 23:21:44 +00:00
logtail: optimize JSON processing (#11671)
Changes made:
* Avoid "encoding/json" for JSON processing, and instead use
"github.com/go-json-experiment/json/jsontext".
Use jsontext.Value.IsValid for validation, which is much faster.
Use jsontext.AppendQuote instead of our own JSON escaping.
* In drainPending, use a different maxLen depending on lowMem.
In lowMem mode, it is better to perform multiple uploads
than it is to construct a large body that OOMs the process.
* In drainPending, if an error is encountered draining,
construct an error message in the logtail JSON format
rather than something that is invalid JSON.
* In appendTextOrJSONLocked, use jsontext.Decoder to check
whether the input is a valid JSON object. This is faster than
the previous approach of unmarshaling into map[string]any and
then re-marshaling that data structure.
This is especially beneficial for network flow logging,
which produces relatively large JSON objects.
* In appendTextOrJSONLocked, enforce maxSize on the input.
If too large, then we may end up in a situation where the logs
can never be uploaded because it exceeds the maximum body size
that the Tailscale logs service accepts.
* Use "tailscale.com/util/truncate" to properly truncate a string
on valid UTF-8 boundaries.
* In general, remove unnecessary spaces in JSON output.
Performance:
name old time/op new time/op delta
WriteText 776ns ± 2% 596ns ± 1% -23.24% (p=0.000 n=10+10)
WriteJSON 110µs ± 0% 9µs ± 0% -91.77% (p=0.000 n=8+8)
name old alloc/op new alloc/op delta
WriteText 448B ± 0% 0B -100.00% (p=0.000 n=10+10)
WriteJSON 37.9kB ± 0% 0.0kB ± 0% -99.87% (p=0.000 n=10+10)
name old allocs/op new allocs/op delta
WriteText 1.00 ± 0% 0.00 -100.00% (p=0.000 n=10+10)
WriteJSON 1.08k ± 0% 0.00k ± 0% -99.91% (p=0.000 n=10+10)
For text payloads, this is 1.30x faster.
For JSON payloads, this is 12.2x faster.
Updates #cleanup
Updates tailscale/corp#18514
Signed-off-by: Joe Tsai <joetsai@digital-static.net>
2024-04-12 19:05:36 +00:00
"github.com/go-json-experiment/json/jsontext"
2023-12-15 23:15:49 +00:00
"tailscale.com/envknob"
2021-10-27 23:21:44 +00:00
"tailscale.com/tstest"
2023-07-21 17:10:39 +00:00
"tailscale.com/tstime"
logtail: optimize JSON processing (#11671)
Changes made:
* Avoid "encoding/json" for JSON processing, and instead use
"github.com/go-json-experiment/json/jsontext".
Use jsontext.Value.IsValid for validation, which is much faster.
Use jsontext.AppendQuote instead of our own JSON escaping.
* In drainPending, use a different maxLen depending on lowMem.
In lowMem mode, it is better to perform multiple uploads
than it is to construct a large body that OOMs the process.
* In drainPending, if an error is encountered draining,
construct an error message in the logtail JSON format
rather than something that is invalid JSON.
* In appendTextOrJSONLocked, use jsontext.Decoder to check
whether the input is a valid JSON object. This is faster than
the previous approach of unmarshaling into map[string]any and
then re-marshaling that data structure.
This is especially beneficial for network flow logging,
which produces relatively large JSON objects.
* In appendTextOrJSONLocked, enforce maxSize on the input.
If too large, then we may end up in a situation where the logs
can never be uploaded because it exceeds the maximum body size
that the Tailscale logs service accepts.
* Use "tailscale.com/util/truncate" to properly truncate a string
on valid UTF-8 boundaries.
* In general, remove unnecessary spaces in JSON output.
Performance:
name old time/op new time/op delta
WriteText 776ns ± 2% 596ns ± 1% -23.24% (p=0.000 n=10+10)
WriteJSON 110µs ± 0% 9µs ± 0% -91.77% (p=0.000 n=8+8)
name old alloc/op new alloc/op delta
WriteText 448B ± 0% 0B -100.00% (p=0.000 n=10+10)
WriteJSON 37.9kB ± 0% 0.0kB ± 0% -99.87% (p=0.000 n=10+10)
name old allocs/op new allocs/op delta
WriteText 1.00 ± 0% 0.00 -100.00% (p=0.000 n=10+10)
WriteJSON 1.08k ± 0% 0.00k ± 0% -99.91% (p=0.000 n=10+10)
For text payloads, this is 1.30x faster.
For JSON payloads, this is 12.2x faster.
Updates #cleanup
Updates tailscale/corp#18514
Signed-off-by: Joe Tsai <joetsai@digital-static.net>
2024-04-12 19:05:36 +00:00
"tailscale.com/util/must"
2020-02-05 22:16:58 +00:00
)
func TestFastShutdown ( t * testing . T ) {
ctx , cancel := context . WithCancel ( context . Background ( ) )
cancel ( )
2021-01-11 14:22:35 +00:00
testServ := httptest . NewServer ( http . HandlerFunc (
func ( w http . ResponseWriter , r * http . Request ) { } ) )
defer testServ . Close ( )
2020-12-21 17:03:39 +00:00
l := NewLogger ( Config {
2021-01-11 14:22:35 +00:00
BaseURL : testServ . URL ,
Add tstest.PanicOnLog(), and fix various problems detected by this.
If a test calls log.Printf, 'go test' horrifyingly rearranges the
output to no longer be in chronological order, which makes debugging
virtually impossible. Let's stop that from happening by making
log.Printf panic if called from any module, no matter how deep, during
tests.
This required us to change the default error handler in at least one
http.Server, as well as plumbing a bunch of logf functions around,
especially in magicsock and wgengine, but also in logtail and backoff.
To add insult to injury, 'go test' also rearranges the output when a
parent test has multiple sub-tests (all the sub-test's t.Logf is always
printed after all the parent tests t.Logf), so we need to screw around
with a special Logf that can point at the "current" t (current_t.Logf)
in some places. Probably our entire way of using subtests is wrong,
since 'go test' would probably like to run them all in parallel if you
called t.Parallel(), but it definitely can't because the're all
manipulating the shared state created by the parent test. They should
probably all be separate toplevel tests instead, with common
setup/teardown logic. But that's a job for another time.
Signed-off-by: Avery Pennarun <apenwarr@tailscale.com>
2020-05-14 02:59:54 +00:00
} , t . Logf )
2021-01-12 21:31:45 +00:00
err := l . Shutdown ( ctx )
if err != nil {
t . Error ( err )
}
2020-02-05 22:16:58 +00:00
}
2020-04-04 21:16:33 +00:00
2021-01-12 21:31:45 +00:00
// maximum number of times a test will call l.Write()
const logLines = 3
type LogtailTestServer struct {
srv * httptest . Server // Log server
uploaded chan [ ] byte
}
func NewLogtailTestHarness ( t * testing . T ) ( * LogtailTestServer , * Logger ) {
ts := LogtailTestServer { }
// max channel backlog = 1 "started" + #logLines x "log line" + 1 "closed"
ts . uploaded = make ( chan [ ] byte , 2 + logLines )
ts . srv = httptest . NewServer ( http . HandlerFunc (
2021-01-10 23:03:57 +00:00
func ( w http . ResponseWriter , r * http . Request ) {
2022-09-15 12:06:59 +00:00
body , err := io . ReadAll ( r . Body )
2021-01-12 21:31:45 +00:00
if err != nil {
t . Error ( "failed to read HTTP request" )
}
ts . uploaded <- body
2021-01-10 23:03:57 +00:00
} ) )
2021-01-12 21:31:45 +00:00
t . Cleanup ( ts . srv . Close )
l := NewLogger ( Config { BaseURL : ts . srv . URL } , t . Logf )
// There is always an initial "logtail started" message
body := <- ts . uploaded
if ! strings . Contains ( string ( body ) , "started" ) {
t . Errorf ( "unknown start logging statement: %q" , string ( body ) )
}
return & ts , l
}
func TestDrainPendingMessages ( t * testing . T ) {
ts , l := NewLogtailTestHarness ( t )
2024-04-16 20:15:13 +00:00
for range logLines {
2021-01-10 23:03:57 +00:00
l . Write ( [ ] byte ( "log line" ) )
}
2021-01-12 21:31:45 +00:00
// all of the "log line" messages usually arrive at once, but poll if needed.
body := ""
for i := 0 ; i <= logLines ; i ++ {
body += string ( <- ts . uploaded )
count := strings . Count ( body , "log line" )
if count == logLines {
break
}
// if we never find count == logLines, the test will eventually time out.
}
err := l . Shutdown ( context . Background ( ) )
if err != nil {
t . Error ( err )
}
}
func TestEncodeAndUploadMessages ( t * testing . T ) {
ts , l := NewLogtailTestHarness ( t )
tests := [ ] struct {
name string
log string
want string
} {
{
"plain text" ,
"log line" ,
"log line" ,
} ,
{
"simple JSON" ,
logtail: optimize JSON processing (#11671)
Changes made:
* Avoid "encoding/json" for JSON processing, and instead use
"github.com/go-json-experiment/json/jsontext".
Use jsontext.Value.IsValid for validation, which is much faster.
Use jsontext.AppendQuote instead of our own JSON escaping.
* In drainPending, use a different maxLen depending on lowMem.
In lowMem mode, it is better to perform multiple uploads
than it is to construct a large body that OOMs the process.
* In drainPending, if an error is encountered draining,
construct an error message in the logtail JSON format
rather than something that is invalid JSON.
* In appendTextOrJSONLocked, use jsontext.Decoder to check
whether the input is a valid JSON object. This is faster than
the previous approach of unmarshaling into map[string]any and
then re-marshaling that data structure.
This is especially beneficial for network flow logging,
which produces relatively large JSON objects.
* In appendTextOrJSONLocked, enforce maxSize on the input.
If too large, then we may end up in a situation where the logs
can never be uploaded because it exceeds the maximum body size
that the Tailscale logs service accepts.
* Use "tailscale.com/util/truncate" to properly truncate a string
on valid UTF-8 boundaries.
* In general, remove unnecessary spaces in JSON output.
Performance:
name old time/op new time/op delta
WriteText 776ns ± 2% 596ns ± 1% -23.24% (p=0.000 n=10+10)
WriteJSON 110µs ± 0% 9µs ± 0% -91.77% (p=0.000 n=8+8)
name old alloc/op new alloc/op delta
WriteText 448B ± 0% 0B -100.00% (p=0.000 n=10+10)
WriteJSON 37.9kB ± 0% 0.0kB ± 0% -99.87% (p=0.000 n=10+10)
name old allocs/op new allocs/op delta
WriteText 1.00 ± 0% 0.00 -100.00% (p=0.000 n=10+10)
WriteJSON 1.08k ± 0% 0.00k ± 0% -99.91% (p=0.000 n=10+10)
For text payloads, this is 1.30x faster.
For JSON payloads, this is 12.2x faster.
Updates #cleanup
Updates tailscale/corp#18514
Signed-off-by: Joe Tsai <joetsai@digital-static.net>
2024-04-12 19:05:36 +00:00
` { "text":"log line"} ` ,
2021-01-12 21:31:45 +00:00
"log line" ,
} ,
}
for _ , tt := range tests {
io . WriteString ( l , tt . log )
body := <- ts . uploaded
2021-08-17 19:14:38 +00:00
data := unmarshalOne ( t , body )
2021-01-12 21:31:45 +00:00
got := data [ "text" ]
if got != tt . want {
t . Errorf ( "%s: got %q; want %q" , tt . name , got . ( string ) , tt . want )
}
ltail , ok := data [ "logtail" ]
if ok {
2022-03-16 23:27:57 +00:00
logtailmap := ltail . ( map [ string ] any )
2021-01-12 21:31:45 +00:00
_ , ok = logtailmap [ "client_time" ]
if ! ok {
t . Errorf ( "%s: no client_time present" , tt . name )
}
} else {
t . Errorf ( "%s: no logtail map present" , tt . name )
}
}
err := l . Shutdown ( context . Background ( ) )
if err != nil {
t . Error ( err )
}
}
2020-07-25 10:40:18 +00:00
func TestLoggerWriteLength ( t * testing . T ) {
2020-12-21 17:03:39 +00:00
lg := & Logger {
2023-07-21 17:10:39 +00:00
clock : tstime . StdClock { } ,
buffer : NewMemoryBuffer ( 1024 ) ,
2020-07-25 10:40:18 +00:00
}
inBuf := [ ] byte ( "some text to encode" )
n , err := lg . Write ( inBuf )
if err != nil {
t . Error ( err )
}
if n != len ( inBuf ) {
t . Errorf ( "logger.Write wrote %d bytes, expected %d" , n , len ( inBuf ) )
}
}
2021-01-12 21:31:45 +00:00
func TestParseAndRemoveLogLevel ( t * testing . T ) {
tests := [ ] struct {
log string
wantLevel int
wantLog string
} {
{
"no level" ,
0 ,
"no level" ,
} ,
{
"[v1] level 1" ,
1 ,
"level 1" ,
} ,
{
"level 1 [v1] " ,
1 ,
"level 1 " ,
} ,
{
"[v2] level 2" ,
2 ,
"level 2" ,
} ,
{
"level [v2] 2" ,
2 ,
"level 2" ,
} ,
{
"[v3] no level 3" ,
0 ,
"[v3] no level 3" ,
} ,
2022-02-18 04:41:49 +00:00
{
"some ignored text then [v\x00JSON]5{\"foo\":1234}" ,
5 ,
` { "foo":1234} ` ,
} ,
2021-01-12 21:31:45 +00:00
}
for _ , tt := range tests {
gotLevel , gotLog := parseAndRemoveLogLevel ( [ ] byte ( tt . log ) )
if gotLevel != tt . wantLevel {
t . Errorf ( "parseAndRemoveLogLevel(%q): got:%d; want %d" ,
tt . log , gotLevel , tt . wantLevel )
}
if string ( gotLog ) != tt . wantLog {
t . Errorf ( "parseAndRemoveLogLevel(%q): got:%q; want %q" ,
tt . log , gotLog , tt . wantLog )
}
}
}
2021-04-15 17:42:02 +00:00
2022-03-16 23:27:57 +00:00
func unmarshalOne ( t * testing . T , body [ ] byte ) map [ string ] any {
2021-08-17 19:14:38 +00:00
t . Helper ( )
2022-03-16 23:27:57 +00:00
var entries [ ] map [ string ] any
2021-08-17 19:14:38 +00:00
err := json . Unmarshal ( body , & entries )
if err != nil {
t . Error ( err )
}
if len ( entries ) != 1 {
t . Fatalf ( "expected one entry, got %d" , len ( entries ) )
}
return entries [ 0 ]
}
2022-01-13 22:02:46 +00:00
2022-02-13 16:54:23 +00:00
type simpleMemBuf struct {
Buffer
buf bytes . Buffer
}
func ( b * simpleMemBuf ) Write ( p [ ] byte ) ( n int , err error ) { return b . buf . Write ( p ) }
func TestEncode ( t * testing . T ) {
tests := [ ] struct {
in string
want string
} {
{
"normal" ,
logtail: optimize JSON processing (#11671)
Changes made:
* Avoid "encoding/json" for JSON processing, and instead use
"github.com/go-json-experiment/json/jsontext".
Use jsontext.Value.IsValid for validation, which is much faster.
Use jsontext.AppendQuote instead of our own JSON escaping.
* In drainPending, use a different maxLen depending on lowMem.
In lowMem mode, it is better to perform multiple uploads
than it is to construct a large body that OOMs the process.
* In drainPending, if an error is encountered draining,
construct an error message in the logtail JSON format
rather than something that is invalid JSON.
* In appendTextOrJSONLocked, use jsontext.Decoder to check
whether the input is a valid JSON object. This is faster than
the previous approach of unmarshaling into map[string]any and
then re-marshaling that data structure.
This is especially beneficial for network flow logging,
which produces relatively large JSON objects.
* In appendTextOrJSONLocked, enforce maxSize on the input.
If too large, then we may end up in a situation where the logs
can never be uploaded because it exceeds the maximum body size
that the Tailscale logs service accepts.
* Use "tailscale.com/util/truncate" to properly truncate a string
on valid UTF-8 boundaries.
* In general, remove unnecessary spaces in JSON output.
Performance:
name old time/op new time/op delta
WriteText 776ns ± 2% 596ns ± 1% -23.24% (p=0.000 n=10+10)
WriteJSON 110µs ± 0% 9µs ± 0% -91.77% (p=0.000 n=8+8)
name old alloc/op new alloc/op delta
WriteText 448B ± 0% 0B -100.00% (p=0.000 n=10+10)
WriteJSON 37.9kB ± 0% 0.0kB ± 0% -99.87% (p=0.000 n=10+10)
name old allocs/op new allocs/op delta
WriteText 1.00 ± 0% 0.00 -100.00% (p=0.000 n=10+10)
WriteJSON 1.08k ± 0% 0.00k ± 0% -99.91% (p=0.000 n=10+10)
For text payloads, this is 1.30x faster.
For JSON payloads, this is 12.2x faster.
Updates #cleanup
Updates tailscale/corp#18514
Signed-off-by: Joe Tsai <joetsai@digital-static.net>
2024-04-12 19:05:36 +00:00
` { "logtail": { "client_time":"1970-01-01T00:02:03.000000456Z","proc_id":7,"proc_seq":1},"text":"normal"} ` + "\n" ,
2022-02-13 16:54:23 +00:00
} ,
{
"and a [v1] level one" ,
logtail: optimize JSON processing (#11671)
Changes made:
* Avoid "encoding/json" for JSON processing, and instead use
"github.com/go-json-experiment/json/jsontext".
Use jsontext.Value.IsValid for validation, which is much faster.
Use jsontext.AppendQuote instead of our own JSON escaping.
* In drainPending, use a different maxLen depending on lowMem.
In lowMem mode, it is better to perform multiple uploads
than it is to construct a large body that OOMs the process.
* In drainPending, if an error is encountered draining,
construct an error message in the logtail JSON format
rather than something that is invalid JSON.
* In appendTextOrJSONLocked, use jsontext.Decoder to check
whether the input is a valid JSON object. This is faster than
the previous approach of unmarshaling into map[string]any and
then re-marshaling that data structure.
This is especially beneficial for network flow logging,
which produces relatively large JSON objects.
* In appendTextOrJSONLocked, enforce maxSize on the input.
If too large, then we may end up in a situation where the logs
can never be uploaded because it exceeds the maximum body size
that the Tailscale logs service accepts.
* Use "tailscale.com/util/truncate" to properly truncate a string
on valid UTF-8 boundaries.
* In general, remove unnecessary spaces in JSON output.
Performance:
name old time/op new time/op delta
WriteText 776ns ± 2% 596ns ± 1% -23.24% (p=0.000 n=10+10)
WriteJSON 110µs ± 0% 9µs ± 0% -91.77% (p=0.000 n=8+8)
name old alloc/op new alloc/op delta
WriteText 448B ± 0% 0B -100.00% (p=0.000 n=10+10)
WriteJSON 37.9kB ± 0% 0.0kB ± 0% -99.87% (p=0.000 n=10+10)
name old allocs/op new allocs/op delta
WriteText 1.00 ± 0% 0.00 -100.00% (p=0.000 n=10+10)
WriteJSON 1.08k ± 0% 0.00k ± 0% -99.91% (p=0.000 n=10+10)
For text payloads, this is 1.30x faster.
For JSON payloads, this is 12.2x faster.
Updates #cleanup
Updates tailscale/corp#18514
Signed-off-by: Joe Tsai <joetsai@digital-static.net>
2024-04-12 19:05:36 +00:00
` { "logtail": { "client_time":"1970-01-01T00:02:03.000000456Z","proc_id":7,"proc_seq":1},"v":1,"text":"and a level one"} ` + "\n" ,
2022-02-13 16:54:23 +00:00
} ,
{
"[v2] some verbose two" ,
logtail: optimize JSON processing (#11671)
Changes made:
* Avoid "encoding/json" for JSON processing, and instead use
"github.com/go-json-experiment/json/jsontext".
Use jsontext.Value.IsValid for validation, which is much faster.
Use jsontext.AppendQuote instead of our own JSON escaping.
* In drainPending, use a different maxLen depending on lowMem.
In lowMem mode, it is better to perform multiple uploads
than it is to construct a large body that OOMs the process.
* In drainPending, if an error is encountered draining,
construct an error message in the logtail JSON format
rather than something that is invalid JSON.
* In appendTextOrJSONLocked, use jsontext.Decoder to check
whether the input is a valid JSON object. This is faster than
the previous approach of unmarshaling into map[string]any and
then re-marshaling that data structure.
This is especially beneficial for network flow logging,
which produces relatively large JSON objects.
* In appendTextOrJSONLocked, enforce maxSize on the input.
If too large, then we may end up in a situation where the logs
can never be uploaded because it exceeds the maximum body size
that the Tailscale logs service accepts.
* Use "tailscale.com/util/truncate" to properly truncate a string
on valid UTF-8 boundaries.
* In general, remove unnecessary spaces in JSON output.
Performance:
name old time/op new time/op delta
WriteText 776ns ± 2% 596ns ± 1% -23.24% (p=0.000 n=10+10)
WriteJSON 110µs ± 0% 9µs ± 0% -91.77% (p=0.000 n=8+8)
name old alloc/op new alloc/op delta
WriteText 448B ± 0% 0B -100.00% (p=0.000 n=10+10)
WriteJSON 37.9kB ± 0% 0.0kB ± 0% -99.87% (p=0.000 n=10+10)
name old allocs/op new allocs/op delta
WriteText 1.00 ± 0% 0.00 -100.00% (p=0.000 n=10+10)
WriteJSON 1.08k ± 0% 0.00k ± 0% -99.91% (p=0.000 n=10+10)
For text payloads, this is 1.30x faster.
For JSON payloads, this is 12.2x faster.
Updates #cleanup
Updates tailscale/corp#18514
Signed-off-by: Joe Tsai <joetsai@digital-static.net>
2024-04-12 19:05:36 +00:00
` { "logtail": { "client_time":"1970-01-01T00:02:03.000000456Z","proc_id":7,"proc_seq":1},"v":2,"text":"some verbose two"} ` + "\n" ,
2022-02-13 16:54:23 +00:00
} ,
{
"{}" ,
2022-05-18 05:28:57 +00:00
` { "logtail": { "client_time":"1970-01-01T00:02:03.000000456Z","proc_id":7,"proc_seq":1}} ` + "\n" ,
2022-02-13 16:54:23 +00:00
} ,
{
` { "foo":"bar"} ` ,
logtail: optimize JSON processing (#11671)
Changes made:
* Avoid "encoding/json" for JSON processing, and instead use
"github.com/go-json-experiment/json/jsontext".
Use jsontext.Value.IsValid for validation, which is much faster.
Use jsontext.AppendQuote instead of our own JSON escaping.
* In drainPending, use a different maxLen depending on lowMem.
In lowMem mode, it is better to perform multiple uploads
than it is to construct a large body that OOMs the process.
* In drainPending, if an error is encountered draining,
construct an error message in the logtail JSON format
rather than something that is invalid JSON.
* In appendTextOrJSONLocked, use jsontext.Decoder to check
whether the input is a valid JSON object. This is faster than
the previous approach of unmarshaling into map[string]any and
then re-marshaling that data structure.
This is especially beneficial for network flow logging,
which produces relatively large JSON objects.
* In appendTextOrJSONLocked, enforce maxSize on the input.
If too large, then we may end up in a situation where the logs
can never be uploaded because it exceeds the maximum body size
that the Tailscale logs service accepts.
* Use "tailscale.com/util/truncate" to properly truncate a string
on valid UTF-8 boundaries.
* In general, remove unnecessary spaces in JSON output.
Performance:
name old time/op new time/op delta
WriteText 776ns ± 2% 596ns ± 1% -23.24% (p=0.000 n=10+10)
WriteJSON 110µs ± 0% 9µs ± 0% -91.77% (p=0.000 n=8+8)
name old alloc/op new alloc/op delta
WriteText 448B ± 0% 0B -100.00% (p=0.000 n=10+10)
WriteJSON 37.9kB ± 0% 0.0kB ± 0% -99.87% (p=0.000 n=10+10)
name old allocs/op new allocs/op delta
WriteText 1.00 ± 0% 0.00 -100.00% (p=0.000 n=10+10)
WriteJSON 1.08k ± 0% 0.00k ± 0% -99.91% (p=0.000 n=10+10)
For text payloads, this is 1.30x faster.
For JSON payloads, this is 12.2x faster.
Updates #cleanup
Updates tailscale/corp#18514
Signed-off-by: Joe Tsai <joetsai@digital-static.net>
2024-04-12 19:05:36 +00:00
` { "logtail": { "client_time":"1970-01-01T00:02:03.000000456Z","proc_id":7,"proc_seq":1},"foo":"bar"} ` + "\n" ,
2022-02-13 16:54:23 +00:00
} ,
2022-02-18 04:41:49 +00:00
{
"foo: [v\x00JSON]0{\"foo\":1}" ,
logtail: optimize JSON processing (#11671)
Changes made:
* Avoid "encoding/json" for JSON processing, and instead use
"github.com/go-json-experiment/json/jsontext".
Use jsontext.Value.IsValid for validation, which is much faster.
Use jsontext.AppendQuote instead of our own JSON escaping.
* In drainPending, use a different maxLen depending on lowMem.
In lowMem mode, it is better to perform multiple uploads
than it is to construct a large body that OOMs the process.
* In drainPending, if an error is encountered draining,
construct an error message in the logtail JSON format
rather than something that is invalid JSON.
* In appendTextOrJSONLocked, use jsontext.Decoder to check
whether the input is a valid JSON object. This is faster than
the previous approach of unmarshaling into map[string]any and
then re-marshaling that data structure.
This is especially beneficial for network flow logging,
which produces relatively large JSON objects.
* In appendTextOrJSONLocked, enforce maxSize on the input.
If too large, then we may end up in a situation where the logs
can never be uploaded because it exceeds the maximum body size
that the Tailscale logs service accepts.
* Use "tailscale.com/util/truncate" to properly truncate a string
on valid UTF-8 boundaries.
* In general, remove unnecessary spaces in JSON output.
Performance:
name old time/op new time/op delta
WriteText 776ns ± 2% 596ns ± 1% -23.24% (p=0.000 n=10+10)
WriteJSON 110µs ± 0% 9µs ± 0% -91.77% (p=0.000 n=8+8)
name old alloc/op new alloc/op delta
WriteText 448B ± 0% 0B -100.00% (p=0.000 n=10+10)
WriteJSON 37.9kB ± 0% 0.0kB ± 0% -99.87% (p=0.000 n=10+10)
name old allocs/op new allocs/op delta
WriteText 1.00 ± 0% 0.00 -100.00% (p=0.000 n=10+10)
WriteJSON 1.08k ± 0% 0.00k ± 0% -99.91% (p=0.000 n=10+10)
For text payloads, this is 1.30x faster.
For JSON payloads, this is 12.2x faster.
Updates #cleanup
Updates tailscale/corp#18514
Signed-off-by: Joe Tsai <joetsai@digital-static.net>
2024-04-12 19:05:36 +00:00
"{\"logtail\":{\"client_time\":\"1970-01-01T00:02:03.000000456Z\",\"proc_id\":7,\"proc_seq\":1},\"foo\":1}\n" ,
2022-02-18 04:41:49 +00:00
} ,
{
"foo: [v\x00JSON]2{\"foo\":1}" ,
logtail: optimize JSON processing (#11671)
Changes made:
* Avoid "encoding/json" for JSON processing, and instead use
"github.com/go-json-experiment/json/jsontext".
Use jsontext.Value.IsValid for validation, which is much faster.
Use jsontext.AppendQuote instead of our own JSON escaping.
* In drainPending, use a different maxLen depending on lowMem.
In lowMem mode, it is better to perform multiple uploads
than it is to construct a large body that OOMs the process.
* In drainPending, if an error is encountered draining,
construct an error message in the logtail JSON format
rather than something that is invalid JSON.
* In appendTextOrJSONLocked, use jsontext.Decoder to check
whether the input is a valid JSON object. This is faster than
the previous approach of unmarshaling into map[string]any and
then re-marshaling that data structure.
This is especially beneficial for network flow logging,
which produces relatively large JSON objects.
* In appendTextOrJSONLocked, enforce maxSize on the input.
If too large, then we may end up in a situation where the logs
can never be uploaded because it exceeds the maximum body size
that the Tailscale logs service accepts.
* Use "tailscale.com/util/truncate" to properly truncate a string
on valid UTF-8 boundaries.
* In general, remove unnecessary spaces in JSON output.
Performance:
name old time/op new time/op delta
WriteText 776ns ± 2% 596ns ± 1% -23.24% (p=0.000 n=10+10)
WriteJSON 110µs ± 0% 9µs ± 0% -91.77% (p=0.000 n=8+8)
name old alloc/op new alloc/op delta
WriteText 448B ± 0% 0B -100.00% (p=0.000 n=10+10)
WriteJSON 37.9kB ± 0% 0.0kB ± 0% -99.87% (p=0.000 n=10+10)
name old allocs/op new allocs/op delta
WriteText 1.00 ± 0% 0.00 -100.00% (p=0.000 n=10+10)
WriteJSON 1.08k ± 0% 0.00k ± 0% -99.91% (p=0.000 n=10+10)
For text payloads, this is 1.30x faster.
For JSON payloads, this is 12.2x faster.
Updates #cleanup
Updates tailscale/corp#18514
Signed-off-by: Joe Tsai <joetsai@digital-static.net>
2024-04-12 19:05:36 +00:00
"{\"logtail\":{\"client_time\":\"1970-01-01T00:02:03.000000456Z\",\"proc_id\":7,\"proc_seq\":1},\"v\":2,\"foo\":1}\n" ,
2022-02-18 04:41:49 +00:00
} ,
2022-02-13 16:54:23 +00:00
}
for _ , tt := range tests {
buf := new ( simpleMemBuf )
lg := & Logger {
2023-07-21 17:10:39 +00:00
clock : tstest . NewClock ( tstest . ClockOpts { Start : time . Unix ( 123 , 456 ) . UTC ( ) } ) ,
2022-05-18 05:28:57 +00:00
buffer : buf ,
procID : 7 ,
procSequence : 1 ,
2022-02-13 16:54:23 +00:00
}
io . WriteString ( lg , tt . in )
got := buf . buf . String ( )
if got != tt . want {
t . Errorf ( "for %q,\n got: %#q\nwant: %#q\n" , tt . in , got , tt . want )
}
if err := json . Compact ( new ( bytes . Buffer ) , buf . buf . Bytes ( ) ) ; err != nil {
t . Errorf ( "invalid output JSON for %q: %s" , tt . in , got )
}
}
}
2023-11-08 19:48:36 +00:00
// Test that even if Logger.Write modifies the input buffer, we still return the
// length of the input buffer, not what we shrank it down to. Otherwise the
// caller will think we did a short write, violating the io.Writer contract.
func TestLoggerWriteResult ( t * testing . T ) {
buf := NewMemoryBuffer ( 100 )
lg := & Logger {
clock : tstest . NewClock ( tstest . ClockOpts { Start : time . Unix ( 123 , 0 ) } ) ,
buffer : buf ,
}
const in = "[v1] foo"
n , err := lg . Write ( [ ] byte ( in ) )
if err != nil {
t . Fatal ( err )
}
if got , want := n , len ( in ) ; got != want {
t . Errorf ( "Write = %v; want %v" , got , want )
}
back , err := buf . TryReadLine ( )
if err != nil {
t . Fatal ( err )
}
logtail: optimize JSON processing (#11671)
Changes made:
* Avoid "encoding/json" for JSON processing, and instead use
"github.com/go-json-experiment/json/jsontext".
Use jsontext.Value.IsValid for validation, which is much faster.
Use jsontext.AppendQuote instead of our own JSON escaping.
* In drainPending, use a different maxLen depending on lowMem.
In lowMem mode, it is better to perform multiple uploads
than it is to construct a large body that OOMs the process.
* In drainPending, if an error is encountered draining,
construct an error message in the logtail JSON format
rather than something that is invalid JSON.
* In appendTextOrJSONLocked, use jsontext.Decoder to check
whether the input is a valid JSON object. This is faster than
the previous approach of unmarshaling into map[string]any and
then re-marshaling that data structure.
This is especially beneficial for network flow logging,
which produces relatively large JSON objects.
* In appendTextOrJSONLocked, enforce maxSize on the input.
If too large, then we may end up in a situation where the logs
can never be uploaded because it exceeds the maximum body size
that the Tailscale logs service accepts.
* Use "tailscale.com/util/truncate" to properly truncate a string
on valid UTF-8 boundaries.
* In general, remove unnecessary spaces in JSON output.
Performance:
name old time/op new time/op delta
WriteText 776ns ± 2% 596ns ± 1% -23.24% (p=0.000 n=10+10)
WriteJSON 110µs ± 0% 9µs ± 0% -91.77% (p=0.000 n=8+8)
name old alloc/op new alloc/op delta
WriteText 448B ± 0% 0B -100.00% (p=0.000 n=10+10)
WriteJSON 37.9kB ± 0% 0.0kB ± 0% -99.87% (p=0.000 n=10+10)
name old allocs/op new allocs/op delta
WriteText 1.00 ± 0% 0.00 -100.00% (p=0.000 n=10+10)
WriteJSON 1.08k ± 0% 0.00k ± 0% -99.91% (p=0.000 n=10+10)
For text payloads, this is 1.30x faster.
For JSON payloads, this is 12.2x faster.
Updates #cleanup
Updates tailscale/corp#18514
Signed-off-by: Joe Tsai <joetsai@digital-static.net>
2024-04-12 19:05:36 +00:00
if got , want := string ( back ) , ` { "logtail": { "client_time":"1970-01-01T00:02:03Z"},"v":1,"text":"foo"} ` + "\n" ; got != want {
2023-11-08 19:48:36 +00:00
t . Errorf ( "mismatch.\n got: %#q\nwant: %#q" , back , want )
}
}
2023-12-15 23:15:49 +00:00
func TestRedact ( t * testing . T ) {
envknob . Setenv ( "TS_OBSCURE_LOGGED_IPS" , "true" )
tests := [ ] struct {
in string
want string
} {
// tests for ipv4 addresses
{
"120.100.30.47" ,
"120.100.x.x" ,
} ,
{
"192.167.0.1/65" ,
"192.167.x.x/65" ,
} ,
{
"node [5Btdd] d:e89a3384f526d251 now using 10.0.0.222:41641 mtu=1360 tx=d81a8a35a0ce" ,
"node [5Btdd] d:e89a3384f526d251 now using 10.0.x.x:41641 mtu=1360 tx=d81a8a35a0ce" ,
} ,
//tests for ipv6 addresses
{
"2001:0db8:85a3:0000:0000:8a2e:0370:7334" ,
"2001:0db8:x" ,
} ,
{
"2345:0425:2CA1:0000:0000:0567:5673:23b5" ,
"2345:0425:x" ,
} ,
{
"2601:645:8200:edf0::c9de/64" ,
"2601:645:x/64" ,
} ,
{
"node [5Btdd] d:e89a3384f526d251 now using 2051:0000:140F::875B:131C mtu=1360 tx=d81a8a35a0ce" ,
"node [5Btdd] d:e89a3384f526d251 now using 2051:0000:x mtu=1360 tx=d81a8a35a0ce" ,
} ,
{
"2601:645:8200:edf0::c9de/64 2601:645:8200:edf0:1ce9:b17d:71f5:f6a3/64" ,
"2601:645:x/64 2601:645:x/64" ,
} ,
//tests for tailscale ip addresses
{
"100.64.5.6" ,
"100.64.5.6" ,
} ,
{
"fd7a:115c:a1e0::/96" ,
"fd7a:115c:a1e0::/96" ,
} ,
//tests for ipv6 and ipv4 together
{
"192.167.0.1 2001:0db8:85a3:0000:0000:8a2e:0370:7334" ,
"192.167.x.x 2001:0db8:x" ,
} ,
{
"node [5Btdd] d:e89a3384f526d251 now using 10.0.0.222:41641 mtu=1360 tx=d81a8a35a0ce 2345:0425:2CA1::0567:5673:23b5" ,
"node [5Btdd] d:e89a3384f526d251 now using 10.0.x.x:41641 mtu=1360 tx=d81a8a35a0ce 2345:0425:x" ,
} ,
{
"100.64.5.6 2091:0db8:85a3:0000:0000:8a2e:0370:7334" ,
"100.64.5.6 2091:0db8:x" ,
} ,
{
"192.167.0.1 120.100.30.47 2041:0000:140F::875B:131B" ,
"192.167.x.x 120.100.x.x 2041:0000:x" ,
} ,
{
"fd7a:115c:a1e0::/96 192.167.0.1 2001:0db8:85a3:0000:0000:8a2e:0370:7334" ,
"fd7a:115c:a1e0::/96 192.167.x.x 2001:0db8:x" ,
} ,
}
for _ , tt := range tests {
gotBuf := redactIPs ( [ ] byte ( tt . in ) )
if string ( gotBuf ) != tt . want {
t . Errorf ( "for %q,\n got: %#q\nwant: %#q\n" , tt . in , gotBuf , tt . want )
}
}
}
logtail: optimize JSON processing (#11671)
Changes made:
* Avoid "encoding/json" for JSON processing, and instead use
"github.com/go-json-experiment/json/jsontext".
Use jsontext.Value.IsValid for validation, which is much faster.
Use jsontext.AppendQuote instead of our own JSON escaping.
* In drainPending, use a different maxLen depending on lowMem.
In lowMem mode, it is better to perform multiple uploads
than it is to construct a large body that OOMs the process.
* In drainPending, if an error is encountered draining,
construct an error message in the logtail JSON format
rather than something that is invalid JSON.
* In appendTextOrJSONLocked, use jsontext.Decoder to check
whether the input is a valid JSON object. This is faster than
the previous approach of unmarshaling into map[string]any and
then re-marshaling that data structure.
This is especially beneficial for network flow logging,
which produces relatively large JSON objects.
* In appendTextOrJSONLocked, enforce maxSize on the input.
If too large, then we may end up in a situation where the logs
can never be uploaded because it exceeds the maximum body size
that the Tailscale logs service accepts.
* Use "tailscale.com/util/truncate" to properly truncate a string
on valid UTF-8 boundaries.
* In general, remove unnecessary spaces in JSON output.
Performance:
name old time/op new time/op delta
WriteText 776ns ± 2% 596ns ± 1% -23.24% (p=0.000 n=10+10)
WriteJSON 110µs ± 0% 9µs ± 0% -91.77% (p=0.000 n=8+8)
name old alloc/op new alloc/op delta
WriteText 448B ± 0% 0B -100.00% (p=0.000 n=10+10)
WriteJSON 37.9kB ± 0% 0.0kB ± 0% -99.87% (p=0.000 n=10+10)
name old allocs/op new allocs/op delta
WriteText 1.00 ± 0% 0.00 -100.00% (p=0.000 n=10+10)
WriteJSON 1.08k ± 0% 0.00k ± 0% -99.91% (p=0.000 n=10+10)
For text payloads, this is 1.30x faster.
For JSON payloads, this is 12.2x faster.
Updates #cleanup
Updates tailscale/corp#18514
Signed-off-by: Joe Tsai <joetsai@digital-static.net>
2024-04-12 19:05:36 +00:00
func TestAppendMetadata ( t * testing . T ) {
var l Logger
l . clock = tstest . NewClock ( tstest . ClockOpts { Start : time . Date ( 2000 , 01 , 01 , 0 , 0 , 0 , 0 , time . UTC ) } )
l . metricsDelta = func ( ) string { return "metrics" }
for _ , tt := range [ ] struct {
skipClientTime bool
skipMetrics bool
procID uint32
procSeq uint64
errDetail string
errData jsontext . Value
level int
want string
} {
{ want : ` "logtail": { "client_time":"2000-01-01T00:00:00Z"},"metrics":"metrics", ` } ,
{ skipClientTime : true , want : ` "metrics":"metrics", ` } ,
{ skipMetrics : true , want : ` "logtail": { "client_time":"2000-01-01T00:00:00Z"}, ` } ,
{ skipClientTime : true , skipMetrics : true , want : ` ` } ,
{ skipClientTime : true , skipMetrics : true , procID : 1 , want : ` "logtail": { "proc_id":1}, ` } ,
{ skipClientTime : true , skipMetrics : true , procSeq : 2 , want : ` "logtail": { "proc_seq":2}, ` } ,
{ skipClientTime : true , skipMetrics : true , procID : 1 , procSeq : 2 , want : ` "logtail": { "proc_id":1,"proc_seq":2}, ` } ,
{ skipMetrics : true , procID : 1 , procSeq : 2 , want : ` "logtail": { "client_time":"2000-01-01T00:00:00Z","proc_id":1,"proc_seq":2}, ` } ,
{ skipClientTime : true , skipMetrics : true , errDetail : "error" , want : ` "logtail": { "error": { "detail":"error"}}, ` } ,
{ skipClientTime : true , skipMetrics : true , errData : jsontext . Value ( "null" ) , want : ` "logtail": { "error": { "bad_data":null}}, ` } ,
{ skipClientTime : true , skipMetrics : true , level : 5 , want : ` "v":5, ` } ,
{ procID : 1 , procSeq : 2 , errDetail : "error" , errData : jsontext . Value ( ` ["something","bad","happened"] ` ) , level : 2 ,
want : ` "logtail": { "client_time":"2000-01-01T00:00:00Z","proc_id":1,"proc_seq":2,"error": { "detail":"error","bad_data":["something","bad","happened"]}},"metrics":"metrics","v":2, ` } ,
} {
got := string ( l . appendMetadata ( nil , tt . skipClientTime , tt . skipMetrics , tt . procID , tt . procSeq , tt . errDetail , tt . errData , tt . level ) )
if got != tt . want {
t . Errorf ( "appendMetadata(%v, %v, %v, %v, %v, %v, %v):\n\tgot %s\n\twant %s" , tt . skipClientTime , tt . skipMetrics , tt . procID , tt . procSeq , tt . errDetail , tt . errData , tt . level , got , tt . want )
}
gotObj := "{" + strings . TrimSuffix ( got , "," ) + "}"
if ! jsontext . Value ( gotObj ) . IsValid ( ) {
t . Errorf ( "`%s`.IsValid() = false, want true" , gotObj )
}
}
}
func TestAppendText ( t * testing . T ) {
var l Logger
l . clock = tstest . NewClock ( tstest . ClockOpts { Start : time . Date ( 2000 , 01 , 01 , 0 , 0 , 0 , 0 , time . UTC ) } )
l . metricsDelta = func ( ) string { return "metrics" }
l . lowMem = true
for _ , tt := range [ ] struct {
text string
skipClientTime bool
procID uint32
procSeq uint64
level int
want string
} {
{ want : ` { "logtail": { "client_time":"2000-01-01T00:00:00Z"},"metrics":"metrics"} ` } ,
{ skipClientTime : true , want : ` { "metrics":"metrics"} ` } ,
{ skipClientTime : true , procID : 1 , procSeq : 2 , want : ` { "logtail": { "proc_id":1,"proc_seq":2},"metrics":"metrics"} ` } ,
{ text : "fizz buzz" , want : ` { "logtail": { "client_time":"2000-01-01T00:00:00Z"},"metrics":"metrics","text":"fizz buzz"} ` } ,
{ text : "\b\f\n\r\t\"\\" , want : ` { "logtail": { "client_time":"2000-01-01T00:00:00Z"},"metrics":"metrics","text":"\b\f\n\r\t\"\\"} ` } ,
{ text : "x" + strings . Repeat ( "😐" , maxSize ) , want : ` { "logtail": { "client_time":"2000-01-01T00:00:00Z"},"metrics":"metrics","text":"x ` + strings . Repeat ( "😐" , 1023 ) + ` …+1044484"} ` } ,
} {
got := string ( l . appendText ( nil , [ ] byte ( tt . text ) , tt . skipClientTime , tt . procID , tt . procSeq , tt . level ) )
if ! strings . HasSuffix ( got , "\n" ) {
t . Errorf ( "`%s` does not end with a newline" , got )
}
got = got [ : len ( got ) - 1 ]
if got != tt . want {
t . Errorf ( "appendText(%v, %v, %v, %v, %v):\n\tgot %s\n\twant %s" , tt . text [ : min ( len ( tt . text ) , 256 ) ] , tt . skipClientTime , tt . procID , tt . procSeq , tt . level , got , tt . want )
}
if ! jsontext . Value ( got ) . IsValid ( ) {
t . Errorf ( "`%s`.IsValid() = false, want true" , got )
}
}
}
func TestAppendTextOrJSON ( t * testing . T ) {
var l Logger
l . clock = tstest . NewClock ( tstest . ClockOpts { Start : time . Date ( 2000 , 01 , 01 , 0 , 0 , 0 , 0 , time . UTC ) } )
l . metricsDelta = func ( ) string { return "metrics" }
l . lowMem = true
for _ , tt := range [ ] struct {
in string
level int
want string
} {
{ want : ` { "logtail": { "client_time":"2000-01-01T00:00:00Z"},"metrics":"metrics"} ` } ,
{ in : "[]" , want : ` { "logtail": { "client_time":"2000-01-01T00:00:00Z"},"metrics":"metrics","text":"[]"} ` } ,
{ level : 1 , want : ` { "logtail": { "client_time":"2000-01-01T00:00:00Z"},"metrics":"metrics","v":1} ` } ,
{ in : ` { } ` , want : ` { "logtail": { "client_time":"2000-01-01T00:00:00Z"}} ` } ,
{ in : ` { } { } ` , want : ` { "logtail": { "client_time":"2000-01-01T00:00:00Z"},"metrics":"metrics","text":" { } { }"} ` } ,
{ in : "{\n\"fizz\"\n:\n\"buzz\"\n}" , want : ` { "logtail": { "client_time":"2000-01-01T00:00:00Z"},"fizz":"buzz"} ` } ,
{ in : ` { "logtail" : "duplicate" } ` , want : ` { "logtail": { "client_time":"2000-01-01T00:00:00Z","error": { "detail":"duplicate logtail member","bad_data":"duplicate"}}} ` } ,
{ in : ` { "fizz" : "buzz" , "logtail" : "duplicate" } ` , want : ` { "logtail": { "client_time":"2000-01-01T00:00:00Z","error": { "detail":"duplicate logtail member","bad_data":"duplicate"}}, "fizz" : "buzz"} ` } ,
{ in : ` { "logtail" : "duplicate" , "fizz" : "buzz" } ` , want : ` { "logtail": { "client_time":"2000-01-01T00:00:00Z","error": { "detail":"duplicate logtail member","bad_data":"duplicate"}} , "fizz" : "buzz"} ` } ,
{ in : ` { "fizz" : "buzz" , "logtail" : "duplicate" , "wizz" : "wuzz" } ` , want : ` { "logtail": { "client_time":"2000-01-01T00:00:00Z","error": { "detail":"duplicate logtail member","bad_data":"duplicate"}}, "fizz" : "buzz" , "wizz" : "wuzz"} ` } ,
{ in : ` { "long":" ` + strings . Repeat ( "a" , maxSize ) + ` "} ` , want : ` { "logtail": { "client_time":"2000-01-01T00:00:00Z","error": { "detail":"entry too large: 262155 bytes","bad_data":" { \"long\":\" ` + strings . Repeat ( "a" , 43681 ) + ` …+218465"}}} ` } ,
} {
got := string ( l . appendTextOrJSONLocked ( nil , [ ] byte ( tt . in ) , tt . level ) )
if ! strings . HasSuffix ( got , "\n" ) {
t . Errorf ( "`%s` does not end with a newline" , got )
}
got = got [ : len ( got ) - 1 ]
if got != tt . want {
t . Errorf ( "appendTextOrJSON(%v, %v):\n\tgot %s\n\twant %s" , tt . in [ : min ( len ( tt . in ) , 256 ) ] , tt . level , got , tt . want )
}
if ! jsontext . Value ( got ) . IsValid ( ) {
t . Errorf ( "`%s`.IsValid() = false, want true" , got )
}
}
}
var sink [ ] byte
func TestAppendTextAllocs ( t * testing . T ) {
lg := & Logger { clock : tstime . StdClock { } }
inBuf := [ ] byte ( "some text to encode" )
procID := uint32 ( 0x24d32ee9 )
procSequence := uint64 ( 0x12346 )
must . Do ( tstest . MinAllocsPerRun ( t , 0 , func ( ) {
sink = lg . appendText ( sink [ : 0 ] , inBuf , false , procID , procSequence , 0 )
} ) )
}
func TestAppendJSONAllocs ( t * testing . T ) {
lg := & Logger { clock : tstime . StdClock { } }
inBuf := [ ] byte ( ` { "fizz":"buzz"} ` )
must . Do ( tstest . MinAllocsPerRun ( t , 1 , func ( ) {
sink = lg . appendTextOrJSONLocked ( sink [ : 0 ] , inBuf , 0 )
} ) )
}
type discardBuffer struct { Buffer }
func ( discardBuffer ) Write ( p [ ] byte ) ( n int , err error ) { return n , nil }
var testdataTextLog = [ ] byte ( ` netcheck: report: udp=true v6=false v6os=true mapvarydest=false hair=false portmap= v4a=174.xxx.xxx.xxx:18168 derp=2 derpdist=1v4:82ms,2v4:18ms,3v4:214ms,4v4:171ms,5v4:196ms,7v4:124ms,8v4:149ms,9v4:56ms,10v4:32ms,11v4:196ms,12v4:71ms,13v4:48ms,14v4:166ms,16v4:85ms,17v4:25ms,18v4:153ms,19v4:176ms,20v4:193ms,21v4:84ms,22v4:182ms,24v4:73ms ` )
var testdataJSONLog = [ ] byte ( ` { "end":"2024-04-08T21:39:15.715291586Z","nodeId":"nQRJBE7CNTRL","physicalTraffic":[ { "dst":"127.x.x.x:2","src":"100.x.x.x:0","txBytes":148,"txPkts":1}, { "dst":"127.x.x.x:2","src":"100.x.x.x:0","txBytes":148,"txPkts":1}, { "dst":"98.x.x.x:1025","rxBytes":640,"rxPkts":5,"src":"100.x.x.x:0","txBytes":640,"txPkts":5}, { "dst":"24.x.x.x:49973","rxBytes":640,"rxPkts":5,"src":"100.x.x.x:0","txBytes":640,"txPkts":5}, { "dst":"73.x.x.x:41641","rxBytes":732,"rxPkts":6,"src":"100.x.x.x:0","txBytes":820,"txPkts":7}, { "dst":"75.x.x.x:1025","rxBytes":640,"rxPkts":5,"src":"100.x.x.x:0","txBytes":640,"txPkts":5}, { "dst":"75.x.x.x:41641","rxBytes":640,"rxPkts":5,"src":"100.x.x.x:0","txBytes":640,"txPkts":5}, { "dst":"174.x.x.x:35497","rxBytes":13008,"rxPkts":98,"src":"100.x.x.x:0","txBytes":26688,"txPkts":150}, { "dst":"47.x.x.x:41641","rxBytes":640,"rxPkts":5,"src":"100.x.x.x:0","txBytes":640,"txPkts":5}, { "dst":"64.x.x.x:41641","rxBytes":640,"rxPkts":5,"src":"100.x.x.x:0","txBytes":640,"txPkts":5}],"start":"2024-04-08T21:39:11.099495616Z","virtualTraffic":[ { "dst":"100.x.x.x:33008","proto":6,"src":"100.x.x.x:22","txBytes":1260,"txPkts":10}, { "dst":"100.x.x.x:0","proto":1,"rxBytes":420,"rxPkts":5,"src":"100.x.x.x:0","txBytes":420,"txPkts":5}, { "dst":"100.x.x.x:32984","proto":6,"src":"100.x.x.x:22","txBytes":1340,"txPkts":10}, { "dst":"100.x.x.x:32998","proto":6,"src":"100.x.x.x:22","txBytes":1020,"txPkts":10}, { "dst":"100.x.x.x:32994","proto":6,"src":"100.x.x.x:22","txBytes":1260,"txPkts":10}, { "dst":"100.x.x.x:32980","proto":6,"src":"100.x.x.x:22","txBytes":1260,"txPkts":10}, { "dst":"100.x.x.x:0","proto":1,"rxBytes":420,"rxPkts":5,"src":"100.x.x.x:0","txBytes":420,"txPkts":5}, { "dst":"100.x.x.x:0","proto":1,"rxBytes":420,"rxPkts":5,"src":"100.x.x.x:0","txBytes":420,"txPkts":5}, { "dst":"100.x.x.x:32950","proto":6,"src":"100.x.x.x:22","txBytes":1340,"txPkts":10}, { "dst":"100.x.x.x:22","proto":6,"src":"100.x.x.x:53332","txBytes":60,"txPkts":1}, { "dst":"100.x.x.x:0","proto":1,"src":"100.x.x.x:0","txBytes":420,"txPkts":5}, { "dst":"100.x.x.x:0","proto":1,"rxBytes":420,"rxPkts":5,"src":"100.x.x.x:0","txBytes":420,"txPkts":5}, { "dst":"100.x.x.x:32966","proto":6,"src":"100.x.x.x:22","txBytes":1260,"txPkts":10}, { "dst":"100.x.x.x:22","proto":6,"src":"100.x.x.x:57882","txBytes":60,"txPkts":1}, { "dst":"100.x.x.x:22","proto":6,"src":"100.x.x.x:53326","txBytes":60,"txPkts":1}, { "dst":"100.x.x.x:22","proto":6,"src":"100.x.x.x:57892","txBytes":60,"txPkts":1}, { "dst":"100.x.x.x:32934","proto":6,"src":"100.x.x.x:22","txBytes":8712,"txPkts":55}, { "dst":"100.x.x.x:0","proto":1,"rxBytes":420,"rxPkts":5,"src":"100.x.x.x:0","txBytes":420,"txPkts":5}, { "dst":"100.x.x.x:32942","proto":6,"src":"100.x.x.x:22","txBytes":1260,"txPkts":10}, { "dst":"100.x.x.x:0","proto":1,"rxBytes":420,"rxPkts":5,"src":"100.x.x.x:0","txBytes":420,"txPkts":5}, { "dst":"100.x.x.x:32964","proto":6,"src":"100.x.x.x:22","txBytes":1260,"txPkts":10}, { "dst":"100.x.x.x:0","proto":1,"rxBytes":420,"rxPkts":5,"src":"100.x.x.x:0","txBytes":420,"txPkts":5}, { "dst":"100.x.x.x:0","proto":1,"rxBytes":420,"rxPkts":5,"src":"100.x.x.x:0","txBytes":420,"txPkts":5}, { "dst":"100.x.x.x:22","proto":6,"src":"100.x.x.x:37238","txBytes":60,"txPkts":1}, { "dst":"100.x.x.x:22","proto":6,"src":"100.x.x.x:37252","txBytes":60,"txPkts":1}]} ` )
func BenchmarkWriteText ( b * testing . B ) {
var l Logger
l . clock = tstime . StdClock { }
l . buffer = discardBuffer { }
b . ReportAllocs ( )
2024-04-16 20:15:13 +00:00
for range b . N {
logtail: optimize JSON processing (#11671)
Changes made:
* Avoid "encoding/json" for JSON processing, and instead use
"github.com/go-json-experiment/json/jsontext".
Use jsontext.Value.IsValid for validation, which is much faster.
Use jsontext.AppendQuote instead of our own JSON escaping.
* In drainPending, use a different maxLen depending on lowMem.
In lowMem mode, it is better to perform multiple uploads
than it is to construct a large body that OOMs the process.
* In drainPending, if an error is encountered draining,
construct an error message in the logtail JSON format
rather than something that is invalid JSON.
* In appendTextOrJSONLocked, use jsontext.Decoder to check
whether the input is a valid JSON object. This is faster than
the previous approach of unmarshaling into map[string]any and
then re-marshaling that data structure.
This is especially beneficial for network flow logging,
which produces relatively large JSON objects.
* In appendTextOrJSONLocked, enforce maxSize on the input.
If too large, then we may end up in a situation where the logs
can never be uploaded because it exceeds the maximum body size
that the Tailscale logs service accepts.
* Use "tailscale.com/util/truncate" to properly truncate a string
on valid UTF-8 boundaries.
* In general, remove unnecessary spaces in JSON output.
Performance:
name old time/op new time/op delta
WriteText 776ns ± 2% 596ns ± 1% -23.24% (p=0.000 n=10+10)
WriteJSON 110µs ± 0% 9µs ± 0% -91.77% (p=0.000 n=8+8)
name old alloc/op new alloc/op delta
WriteText 448B ± 0% 0B -100.00% (p=0.000 n=10+10)
WriteJSON 37.9kB ± 0% 0.0kB ± 0% -99.87% (p=0.000 n=10+10)
name old allocs/op new allocs/op delta
WriteText 1.00 ± 0% 0.00 -100.00% (p=0.000 n=10+10)
WriteJSON 1.08k ± 0% 0.00k ± 0% -99.91% (p=0.000 n=10+10)
For text payloads, this is 1.30x faster.
For JSON payloads, this is 12.2x faster.
Updates #cleanup
Updates tailscale/corp#18514
Signed-off-by: Joe Tsai <joetsai@digital-static.net>
2024-04-12 19:05:36 +00:00
must . Get ( l . Write ( testdataTextLog ) )
}
}
func BenchmarkWriteJSON ( b * testing . B ) {
var l Logger
l . clock = tstime . StdClock { }
l . buffer = discardBuffer { }
b . ReportAllocs ( )
2024-04-16 20:15:13 +00:00
for range b . N {
logtail: optimize JSON processing (#11671)
Changes made:
* Avoid "encoding/json" for JSON processing, and instead use
"github.com/go-json-experiment/json/jsontext".
Use jsontext.Value.IsValid for validation, which is much faster.
Use jsontext.AppendQuote instead of our own JSON escaping.
* In drainPending, use a different maxLen depending on lowMem.
In lowMem mode, it is better to perform multiple uploads
than it is to construct a large body that OOMs the process.
* In drainPending, if an error is encountered draining,
construct an error message in the logtail JSON format
rather than something that is invalid JSON.
* In appendTextOrJSONLocked, use jsontext.Decoder to check
whether the input is a valid JSON object. This is faster than
the previous approach of unmarshaling into map[string]any and
then re-marshaling that data structure.
This is especially beneficial for network flow logging,
which produces relatively large JSON objects.
* In appendTextOrJSONLocked, enforce maxSize on the input.
If too large, then we may end up in a situation where the logs
can never be uploaded because it exceeds the maximum body size
that the Tailscale logs service accepts.
* Use "tailscale.com/util/truncate" to properly truncate a string
on valid UTF-8 boundaries.
* In general, remove unnecessary spaces in JSON output.
Performance:
name old time/op new time/op delta
WriteText 776ns ± 2% 596ns ± 1% -23.24% (p=0.000 n=10+10)
WriteJSON 110µs ± 0% 9µs ± 0% -91.77% (p=0.000 n=8+8)
name old alloc/op new alloc/op delta
WriteText 448B ± 0% 0B -100.00% (p=0.000 n=10+10)
WriteJSON 37.9kB ± 0% 0.0kB ± 0% -99.87% (p=0.000 n=10+10)
name old allocs/op new allocs/op delta
WriteText 1.00 ± 0% 0.00 -100.00% (p=0.000 n=10+10)
WriteJSON 1.08k ± 0% 0.00k ± 0% -99.91% (p=0.000 n=10+10)
For text payloads, this is 1.30x faster.
For JSON payloads, this is 12.2x faster.
Updates #cleanup
Updates tailscale/corp#18514
Signed-off-by: Joe Tsai <joetsai@digital-static.net>
2024-04-12 19:05:36 +00:00
must . Get ( l . Write ( testdataJSONLog ) )
}
}
