Use a line-buffered logger to deamplify write syscalls #6954

dannykopping · 2022-08-23T09:23:52Z

What this PR does / why we need it:
We initialise a global logger in pkg/util/log/log.go and use it extensively throughout the Loki codebase. Every time we write a log message, a write syscall is invoked. Syscalls are problematic because they transition the process from userspace to kernelspace, which means:

a context-switch is incurred, which is inherently expensive (1-2 microseconds)
the goroutine executing the code is blocked
the underlying OS thread (M in the go scheduler model) is also blocked
the goroutine has to be rescheduled once the syscall exits
the go scheduler may need to spawn additional OS threads if all are blocked in syscalls - which can also be expensive

This change introduces the use of a line-buffered logger. It has a buffer of 256 entries, and once that buffer is filled it will flush to disk. However, a situation will arise in which that buffer remains somewhat empty for a period of time, so there is a periodic flush mechanism, configured to flush every 100ms. There is also a preallocated bytes slice of 10MB which is reused, to avoid excessive slice resizing & garbage collection.

This does mean that we could lose up to 256 log messages in case of an ungraceful termination of the process, but this would need to be precisely timed within the 100ms flushes - in other words, the likelihood is low, and generally we shouldn't kill -9 any Loki process.

Which issue(s) this PR fixes:
N/A

Special notes for your reviewer:
This PR uses my private fork of go-kit/log; once we've validated this to work in our environment I will attempt to upstream the change.

Line-buffering is common, and in Linux the stdout stream is line-buffered when attached to a terminal.

We also currently make use of the log.NewSyncWriter writer, which is totally unnecessary since write syscalls are threadsafe by nature, and we also don't need to worry about out-of-order logs anymore. Removing this should also eliminate some contention, and there's a config option to control this separately while we test this out.

Checklist

Documentation added
Tests updated
Is this an important fix or new feature? Add an entry in the CHANGELOG.md.
Changes that require user attention or interaction to upgrade are documented in docs/sources/upgrading/_index.md

grafanabot · 2022-08-23T09:39:36Z

./tools/diff_coverage.sh ../loki-main/test_results.txt test_results.txt ingester,distributor,querier,querier/queryrange,iter,storage,chunkenc,logql,loki

Change in test coverage per package. Green indicates 0 or positive change, red indicates that test coverage for a package fell.

+           ingester	0%
+        distributor	0%
+            querier	0%
+ querier/queryrange	0%
+               iter	0%
+            storage	0%
+           chunkenc	0%
+              logql	0%
+               loki	0%

Signed-off-by: Danny Kopping <danny.kopping@grafana.com>

grafanabot · 2022-10-03T06:44:56Z

./tools/diff_coverage.sh ../loki-main/test_results.txt test_results.txt ingester,distributor,querier,querier/queryrange,iter,storage,chunkenc,logql,loki

Change in test coverage per package. Green indicates 0 or positive change, red indicates that test coverage for a package fell.

+           ingester	0%
+        distributor	0%
+            querier	0%
+ querier/queryrange	0%
+               iter	0%
+            storage	0%
+           chunkenc	0%
+              logql	0%
+               loki	0%

Refactor usages of InitLogger Signed-off-by: Danny Kopping <danny.kopping@grafana.com>

Signed-off-by: Danny Kopping <danny.kopping@grafana.com>

grafanabot · 2022-10-03T07:30:32Z

./tools/diff_coverage.sh ../loki-main/test_results.txt test_results.txt ingester,distributor,querier,querier/queryrange,iter,storage,chunkenc,logql,loki

Change in test coverage per package. Green indicates 0 or positive change, red indicates that test coverage for a package fell.

+           ingester	0%
+        distributor	0%
+            querier	0%
+ querier/queryrange	0%
+               iter	0%
+            storage	0%
+           chunkenc	0%
+              logql	0%
+               loki	0.1%

Signed-off-by: Danny Kopping <danny.kopping@grafana.com>

grafanabot · 2022-10-03T07:38:12Z

./tools/diff_coverage.sh ../loki-main/test_results.txt test_results.txt ingester,distributor,querier,querier/queryrange,iter,storage,chunkenc,logql,loki

Change in test coverage per package. Green indicates 0 or positive change, red indicates that test coverage for a package fell.

+           ingester	0%
+        distributor	0%
+            querier	0%
- querier/queryrange	-0.1%
+               iter	0%
+            storage	0%
+           chunkenc	0%
+              logql	0%
+               loki	0.1%

salvacorts · 2022-10-03T08:23:07Z

pkg/util/log/log.go

+
+	// buffered logger settings
+	var (
+		logEntries    uint32 = 256                    // buffer up to 256 log lines in memory before flushing to a write(2) syscall


Would be nice if these could be configured.

Maybe in a subsequent PR we can make it configurable, but I don't think it's worth it personally.
It's probably already tuned ~optimally, so I don't think a user would need to configure it.

salvacorts · 2022-10-03T08:25:14Z

we shouldn't kill -9 any Loki process.

I'm more concerned about OOMed processes. If a process runs out of memory, it'll be killed and we might lose important logs to assess what made the memory of the process increase.

dannykopping · 2022-10-03T08:35:21Z

we shouldn't kill -9 any Loki process.

I'm more concerned about OOMed processes. If a process runs out of memory, it'll be killed and we might lose important logs to assess what made the memory of the process increase.

That's true, but generally logs are not useful in diagnosing problems of this nature - continuous profiling would be the solution here.

trevorwhitney

This looks great, a welcome addition.

One other thought. Do we want to be able to flush this buffer when the /flush endpoint on an ingester is called (or any other stateful component we do manual scale downs of)?

trevorwhitney · 2022-10-03T14:42:14Z

pkg/util/log/log.go

+	// buffered logger settings
+	var (
+		logEntries    uint32 = 256                    // buffer up to 256 log lines in memory before flushing to a write(2) syscall
+		logBufferSize uint32 = 10e6                   // 10MB


what happens if 256 entries goes over 10MB? Will the buffer also flush on size?

The preallocated buffer is just to prevent slice resizing, and because it's reused it prevents unnecessary GC.
If 10MB is exceeded then the buffer's underlying slice will grow, so nothing will really happen - it won't flush on size.

trevorwhitney · 2022-10-03T14:43:26Z

pkg/util/log/log.go

+	var writer io.Writer
+	if buffered {
+		// TODO: it's technically possible here to lose logs between the 100ms flush and the process being killed
+		// 	=> call buf.Flush() in a signal handler if this is a concern, but this is unlikely to be a problem


is there a cost to also calling Flush in a signal handler? not necessary for this PR, but feels like a pretty cheap and easy way to hedge against this edge case.

No real cost, except last time I looked the signal handler is buried inside the weaveworks/common lib and it'll be a bit of a chore to work around that. Maybe I'm wrong though?

dannykopping

Thanks for the review!

dannykopping · 2022-10-03T14:47:34Z

pkg/util/log/log.go

+	// buffered logger settings
+	var (
+		logEntries    uint32 = 256                    // buffer up to 256 log lines in memory before flushing to a write(2) syscall
+		logBufferSize uint32 = 10e6                   // 10MB


The preallocated buffer is just to prevent slice resizing, and because it's reused it prevents unnecessary GC.
If 10MB is exceeded then the buffer's underlying slice will grow, so nothing will really happen - it won't flush on size.

dannykopping · 2022-10-03T14:48:22Z

pkg/util/log/log.go

+	var writer io.Writer
+	if buffered {
+		// TODO: it's technically possible here to lose logs between the 100ms flush and the process being killed
+		// 	=> call buf.Flush() in a signal handler if this is a concern, but this is unlikely to be a problem


No real cost, except last time I looked the signal handler is buried inside the weaveworks/common lib and it'll be a bit of a chore to work around that. Maybe I'm wrong though?

dannykopping · 2022-10-03T14:49:40Z

One other thought. Do we want to be able to flush this buffer when the /flush endpoint on an ingester is called (or any other stateful component we do manual scale downs of)?

Calling the /flush endpoint will trigger a bunch of actions which will produce logs themselves - ultimately we just need a shutdown handler here to cover all cases I believe.

Promtail is using the line-buffered logger (#6954), and log messages were not being printed on exit

We initialise a global logger in `pkg/util/log/log.go` and use it extensively throughout the Loki codebase. Every time we write a log message, a `write` syscall is invoked. Syscalls are problematic because they transition the process from userspace to kernelspace, which means: - a context-switch is incurred, which is inherently expensive ([1-2 microseconds](https://eli.thegreenplace.net/2018/measuring-context-switching-and-memory-overheads-for-linux-threads/)) - the goroutine executing the code is **blocked** - the underlying OS thread (_M_ in the go scheduler model) is **also blocked** - the goroutine has to be rescheduled once the syscall exits - the go scheduler may need to spawn additional OS threads if all are blocked in syscalls - which can also be expensive This change introduces the use of a line-buffered logger. It has a buffer of [256](https://gist.github.com/dannykopping/0704db32c0b08751d1d2494efaa734c2) entries, and once that buffer is filled it will flush to disk. However, a situation will arise in which that buffer remains somewhat empty for a period of time, so there is a periodic flush mechanism, configured to flush every 100ms. There is also a preallocated bytes slice of 10MB which is reused, to avoid excessive slice resizing & garbage collection. This does mean that we could lose up to 256 log messages in case of an ungraceful termination of the process, but this would need to be precisely timed within the 100ms flushes - in other words, the likelihood is low, and generally we shouldn't `kill -9` any Loki process.

Promtail is using the line-buffered logger (grafana#6954), and log messages were not being printed on exit

We initialise a global logger in `pkg/util/log/log.go` and use it extensively throughout the Loki codebase. Every time we write a log message, a `write` syscall is invoked. Syscalls are problematic because they transition the process from userspace to kernelspace, which means: - a context-switch is incurred, which is inherently expensive ([1-2 microseconds](https://eli.thegreenplace.net/2018/measuring-context-switching-and-memory-overheads-for-linux-threads/)) - the goroutine executing the code is **blocked** - the underlying OS thread (_M_ in the go scheduler model) is **also blocked** - the goroutine has to be rescheduled once the syscall exits - the go scheduler may need to spawn additional OS threads if all are blocked in syscalls - which can also be expensive This change introduces the use of a line-buffered logger. It has a buffer of [256](https://gist.github.com/dannykopping/0704db32c0b08751d1d2494efaa734c2) entries, and once that buffer is filled it will flush to disk. However, a situation will arise in which that buffer remains somewhat empty for a period of time, so there is a periodic flush mechanism, configured to flush every 100ms. There is also a preallocated bytes slice of 10MB which is reused, to avoid excessive slice resizing & garbage collection. This does mean that we could lose up to 256 log messages in case of an ungraceful termination of the process, but this would need to be precisely timed within the 100ms flushes - in other words, the likelihood is low, and generally we shouldn't `kill -9` any Loki process.

Promtail is using the line-buffered logger (grafana#6954), and log messages were not being printed on exit

We initialise a global logger in `pkg/util/log/log.go` and use it extensively throughout the Loki codebase. Every time we write a log message, a `write` syscall is invoked. Syscalls are problematic because they transition the process from userspace to kernelspace, which means: - a context-switch is incurred, which is inherently expensive ([1-2 microseconds](https://eli.thegreenplace.net/2018/measuring-context-switching-and-memory-overheads-for-linux-threads/)) - the goroutine executing the code is **blocked** - the underlying OS thread (_M_ in the go scheduler model) is **also blocked** - the goroutine has to be rescheduled once the syscall exits - the go scheduler may need to spawn additional OS threads if all are blocked in syscalls - which can also be expensive This change introduces the use of a line-buffered logger. It has a buffer of [256](https://gist.github.com/dannykopping/0704db32c0b08751d1d2494efaa734c2) entries, and once that buffer is filled it will flush to disk. However, a situation will arise in which that buffer remains somewhat empty for a period of time, so there is a periodic flush mechanism, configured to flush every 100ms. There is also a preallocated bytes slice of 10MB which is reused, to avoid excessive slice resizing & garbage collection. This does mean that we could lose up to 256 log messages in case of an ungraceful termination of the process, but this would need to be precisely timed within the 100ms flushes - in other words, the likelihood is low, and generally we shouldn't `kill -9` any Loki process.

Promtail is using the line-buffered logger (grafana#6954), and log messages were not being printed on exit

pull-request-size bot added the size/M label Aug 23, 2022

dannykopping mentioned this pull request Aug 23, 2022

Upgrade prometheus/client_golang and reconfigure to restore go_sched.* metrics #6957

Merged

4 tasks

Danny Kopping added 3 commits October 1, 2022 10:55

Using go-kit/log fork with line-buffered logger

d9aa9ec

Signed-off-by: Danny Kopping <danny.kopping@grafana.com>

Adding flush histogram metric

545a052

Signed-off-by: Danny Kopping <danny.kopping@grafana.com>

Revendoring implementation and refactoring

10322f0

Signed-off-by: Danny Kopping <danny.kopping@grafana.com>

dannykopping force-pushed the dannykopping/buffered-logs branch from 76e0dc4 to 10322f0 Compare October 3, 2022 06:39

Add config options to control buffered/sync settings

10464aa

Refactor usages of InitLogger Signed-off-by: Danny Kopping <danny.kopping@grafana.com>

pull-request-size bot added size/L and removed size/M labels Oct 3, 2022

Appeasing the linter

df135f6

Signed-off-by: Danny Kopping <danny.kopping@grafana.com>

go mod tidy

5db53b7

Signed-off-by: Danny Kopping <danny.kopping@grafana.com>

dannykopping marked this pull request as ready for review October 3, 2022 07:56

dannykopping requested a review from a team as a code owner October 3, 2022 07:56

salvacorts reviewed Oct 3, 2022

View reviewed changes

salvacorts approved these changes Oct 3, 2022

View reviewed changes

trevorwhitney approved these changes Oct 3, 2022

View reviewed changes

dannykopping commented Oct 3, 2022

View reviewed changes

dannykopping merged commit 6bf5b5d into grafana:main Oct 4, 2022

dannykopping deleted the dannykopping/buffered-logs branch October 4, 2022 11:47

This was referenced Oct 4, 2022

Observe how long we block writing our own logs #6818

Closed

Recut k118 with several improvements #7344

Merged

dannykopping mentioned this pull request Oct 12, 2022

Promtail: flush logs on exit #7400

Merged

5 tasks

dannykopping pushed a commit that referenced this pull request Oct 12, 2022

Promtail: flush logs on exit (#7400)

33bf36a

Promtail is using the line-buffered logger (#6954), and log messages were not being printed on exit

lxwzy pushed a commit to lxwzy/loki that referenced this pull request Nov 7, 2022

Promtail: flush logs on exit (grafana#7400)

c94827a

Promtail is using the line-buffered logger (grafana#6954), and log messages were not being printed on exit

changhyuni pushed a commit to changhyuni/loki that referenced this pull request Nov 8, 2022

Promtail: flush logs on exit (grafana#7400)

eb2f695

Promtail is using the line-buffered logger (grafana#6954), and log messages were not being printed on exit

Abuelodelanada pushed a commit to canonical/loki that referenced this pull request Dec 1, 2022

Promtail: flush logs on exit (grafana#7400)

88ac74c

Promtail is using the line-buffered logger (grafana#6954), and log messages were not being printed on exit

dannykopping mentioned this pull request Dec 14, 2022

Line-buffered logger go-kit/log#29

Closed

This was referenced Jul 14, 2023

Very high goroutine numbers in ingester grafana/mimir#397

Closed

Add buffered logger grafana/mimir#5506

Merged

dannykopping mentioned this pull request Jul 28, 2023

Update dskit #10091

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Use a line-buffered logger to deamplify write syscalls #6954

Use a line-buffered logger to deamplify write syscalls #6954

dannykopping commented Aug 23, 2022 •

edited

Loading

grafanabot commented Aug 23, 2022

grafanabot commented Oct 3, 2022

grafanabot commented Oct 3, 2022

grafanabot commented Oct 3, 2022

salvacorts Oct 3, 2022

dannykopping Oct 3, 2022

salvacorts commented Oct 3, 2022

dannykopping commented Oct 3, 2022

trevorwhitney left a comment

trevorwhitney Oct 3, 2022

dannykopping Oct 3, 2022

trevorwhitney Oct 3, 2022

dannykopping Oct 3, 2022

dannykopping left a comment

dannykopping Oct 3, 2022

dannykopping Oct 3, 2022

dannykopping commented Oct 3, 2022

Use a line-buffered logger to deamplify write syscalls #6954

Use a line-buffered logger to deamplify write syscalls #6954

Conversation

dannykopping commented Aug 23, 2022 • edited Loading

grafanabot commented Aug 23, 2022

grafanabot commented Oct 3, 2022

grafanabot commented Oct 3, 2022

grafanabot commented Oct 3, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

salvacorts commented Oct 3, 2022

dannykopping commented Oct 3, 2022

trevorwhitney left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dannykopping left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dannykopping commented Oct 3, 2022

dannykopping commented Aug 23, 2022 •

edited

Loading