Remote log via logger_proxy

I was looking through all documentation and haven’t found guide: how to route all logs from slave node to master, so I’m sharing this for others to find it.

You need to set group_leader on slave node processes to a process on master node, or set it as a gl field in metadata. In this case logger will automatically copy log events to master and route them according to rules.

I’ve found two ways to achieve it:

  1. in launcher function (called as -s module fun in startup arguments) I calculate some group_leader from master node and assign it to the first process. Then all children will automatically inherit it.
    Mention that you cannot call: rpc:call(MasterNode, erlang, group_leader, []) because this call will return your local group_leader on your slave node (rpc call inverts what we try to do), you need to find some other process, for example take group_leader from logger_sup

  2. in some other function that is running later, you can modify primary metadata for whole logger on slave node and set gl key to the pid on master node. This allows to reconfigure target for logs.

Btw, big thanks for the logger. It is designed almost identically to our internal flussonic events subsystem, but we were too lazy to opensource it in 2015 =(( I will try not to repeat this mistake and opensource our other components.

5 Likes

Thanks for sharing! I wonder if there is an opportunity to improve peer in this area so that it can install a proper log handler that redirects logs from the peer to the main node. Not sure how common it is to want the actual log events redirected.

One neat thing you can do in peer when using ct is to capture and check the output of the node, like is done here: otp/peer_SUITE.erl at master · erlang/otp · GitHub

1 Like

Thanks, will check it!

All this was made for easier migration to json logs and it was rather easy to do it with your architecture.

Comparing to error logger, your architecture of logger was so close to our own that sometimes it looked like there was some communication =)

One of the difference is our protection mechanism. I’m a bit afraid of peeking at message_queue_len (locks, etc), so we tried to periodically self-send message to handler process and look in ets, how long ago this message was received.

You have refused from processes in handlers and it is nice.

1 Like

We took a lot of ideas and inspiration from the way that python does logging. It is also rather similar to how Elixir’s logger works, so I suppose that it is a pretty intuitive way to construct logging services.

Doing message_queue_len on self() is a relatively cheap operation that we have not heard of any issues with using yet.

2 Likes

Doing message_queue_len on self() is a relatively cheap operation

Yes, indeed. It is not possible to do message_queue_len on hot path on another process =(

Seems that I’ve overengineered it, because we suffered a lot with old lager implementation that could ruine performance by adding penalty to processes that were calling debug, while writing disk log on slow HDD.

1 Like

Could you elaborate on the performance implications of using message_queue_len on another process than self()?

1 Like

We’ve met many times that when we ask some process like WAL disk writer: what is your message_queue_len in runtime from different processes, this place becomes a mutex with huge wait time.

Threads are blocked on it, cpu is low, reductions low, system just doesn’t work and is stuck in mutexes.

1 Like

Seems like it could be an area of the VM improvement using a lock-free read of the queue length counter, so that it can be read without acquiring a mutex. In many cases, such as in the logger, the producer, being another process from the consumer, needs to back off if the queue length is high, and it doesn’t need to get the precise value of the queue length but rather an indicator that the queue is long enough to trigger a different code path.

1 Like

I think that yes, it may be optimized, especially when we add some considerations. It is not interesting to know exact number: 50 000 or 50 001 messages, it is just bigger than 20 000, so we should just consider it busy.

1 Like

Looking at the implementation of process info, it doesn’t seem like there should be a performance difference between probing message_queue_len from the self or another process.

1 Like

We’ve got into situation when 500 processes from 40 different cores are checking process_info and it leads to huge wait time in mutex according to lcnt

1 Like

Doing a process_info message_queue_len will result in the outer mailbox lock being taken three times for the inspected process:

  1. Send signal to inspect mailbox length
  2. Bring signal from outer to inner queue
  3. Lock queue for inspection

When doing it on yourself you only need to lock the queue for the last step.

1 Like

Lukas, what do you think of introducing a light-weight type of checking the approximate queue length of another processes without the extra overhead of locking?

1 Like

Since the implementation of parallel send, it has become harder to get that value as the external signal queue may consist of multiple signal queues. If we ever do more parallelization optimization for the external signal queue it will only become harder to do so.

1 Like

Is that still difficult even if only an approximation of that length is desired? I.e. to have an atomic queue length counter with lock-free read access that would tell if the queue length is “significant or not”, so that another process could enable back-pressure in cases when the consumer’s queue length is “significant”, without incurring the performance hit by mutex locking.

1 Like

The problem would be to know where to read the value as a process can switch between having multiple to a single external message queue at any time, so you would risk getting segfault if you just read without first synchronizing. Most likely this is a solvable issue though, though for an unknown future implementation it may not be and if we add such an API now, then we limit what we can do in the future. So we must think very carefully when adding introspection or limits to the signal queue.

1 Like

It sounds very much in line with what I wanted to have in erlang:system_monitor: ability to report long_message_queue same way it happens for long_gc or large_heap.

Upon receipt of such message it would be easy to set up some fast-to-check global state (e.g. persistent_term that holds immediate value).

1 Like

The idea is that we do not need to know the exact number. Just a flag that tells, that message queue len has rised higher than HWM and haven’t fallen yet below LWM

1 Like