Skip to content

Logger improvements#74

Merged
ortex merged 3 commits into
roc-streaming:mainfrom
gavv:main
Apr 19, 2023
Merged

Logger improvements#74
ortex merged 3 commits into
roc-streaming:mainfrom
gavv:main

Conversation

@gavv

@gavv gavv commented Apr 8, 2023

Copy link
Copy Markdown
Member

This PR contains two commits:

  • minor refactoring in log.go
  • decoupling of C and Go logging threads

More details about the second commit:

I noticed that when user calls SetLogger/SetLoggerFunc to provide custom log handler, or configures standard logger to use custom output writer, it may happen that our C threads invoke arbitrary complex user's go code.

I feel that invoking random user's go code on random C threads may be dangerous, at best it can confuse go scheduler and probably cause performance issues, though I don't have specific examples on top of my head.

Anyway, I just decoupled this threads: C callback now writes messages to a channel, and user's go code is invoked in a separate goroutine which reads messages from that channel. Now we can be sure that user's callback stay in "go world" and callbacks invoked on C thread is small and minimal and is completely controlled by us.

@gavv gavv added the status: ready for review Pull request can be reviewed label Apr 8, 2023
@coveralls

coveralls commented Apr 8, 2023

Copy link
Copy Markdown
Collaborator

Coverage Status

Coverage: 88.592% (+0.6%) from 87.971% when pulling 63bb26c on gavv:main into ec43d2b on roc-streaming:main.

@ortex

ortex commented Apr 8, 2023

Copy link
Copy Markdown
Member

LGTM

slightly related stuff:
Need to fix comments for LogInfo and LogTrace levels.

	// LogError enables informational messages and above.
	LogInfo LogLevel = 2
...
	// LogDebug enables extra verbose logging, which may hurt performance
	// and should not be used in production.
	LogTrace LogLevel = 4

@gavv

gavv commented Apr 8, 2023

Copy link
Copy Markdown
Member Author

Need to fix comments for LogInfo and LogTrace levels.

Fixed.

@gavv gavv requested review from Asalle and ortex April 9, 2023 13:15
@gavv

gavv commented Apr 11, 2023

Copy link
Copy Markdown
Member Author

I feel that invoking random user's go code on random C threads may be dangerous, at best it can confuse go scheduler and probably cause performance issues, though I don't have specific examples on top of my head.

So I dug into it a bit more.

It works as follows:

  • C thread invokes Go entry point

  • Go attaches temporary M to the C thread, switches to M's stack, and invokes LockOSThread (pin goroutine to system thread)

  • Go invokes our callback

  • our callback is executed on the C thread and Go stack; it's allowed to block; it's not allowed to switch goroutines; when it blocks, instead of scheduling another goroutine, it's OS thread is suspended on a futex until woke up from other Go threads;

Conclusion:

  • my feeling was right, it's not OK to invoke arbitrary user code in logger callback, because executing code in a goroutine after LockOSThread may have performance penalties and user may not expect that their code will run in such environment

  • luckily, it's OK to block in Go callback on C thread, so a blocking write to a channel that I'm doing in this PR is acceptable; the C thread will just sleep, as intended

Reference:

Test example: https://gist.github.com/gavv/71c60e9aedd2aeb9ce036ee24d94d0c7

@gavv gavv mentioned this pull request Apr 19, 2023
@ortex ortex merged commit 0d0aa8b into roc-streaming:main Apr 19, 2023
@gavv gavv mentioned this pull request Apr 20, 2023
4 tasks
@gavv gavv removed the status: ready for review Pull request can be reviewed label May 16, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants