logqueue-disk: serialize outside of the lock in the source threads #3746

alltilla · 2021-08-02T14:31:53Z

It is common to have multiple source threads.
When we use disk-buffer, the message's serialization and writing it to the disk happen in the source thread.

Currently, the serialization happens while the source thread is holding the LogQueue's lock. Also it is inbetween two accesses of the QDisk.
If we just simply move the serialization outside the lock, we are not guaranteed to have the same QDisk state, as we were having beforehand, so it is better to move the whole serialization between QDisk is ever accessed and the lock is obtained.

This can yield significant performance improvement, because while the source threads are doing their slow serialization, the destination thread can process messages from the QDisk. In my local measurements, this change introduced a 40-50% performance gain compared to syslog-ng-3.32.1.

No news file needed, IMO.

Signed-off-by: Attila Szakacs [email protected]

MrAnno · 2021-08-02T14:53:36Z

This can yield significant performance improvement

Could you share the measurement, please? As far as I remember, it was a 60% improvement in general when the reliable disk-buffer was used.

The non-reliable disk-buffer has some qout/qoverflow move logic that slows us down, we're investigating that one separately.

No news file needed, IMO.

I think we could add a NEWS entry about the overall performance improvement in the last pull request.

I'm sharing two flame graphs, which show the ratios between the actual disk writes and the serialization/deserialization logic:

kira-syslogng · 2021-08-02T14:55:45Z

Build SUCCESS

modules/diskq/logqueue-disk-non-reliable.c

alltilla · 2021-08-02T16:27:31Z

This can yield significant performance improvement

Could you share the measurement, please? As far as I remember, it was a 60% improvement in general when the reliable disk-buffer was used.

The non-reliable disk-buffer has some qout/qoverflow move logic that slows us down, we're investigating that one separately.

No news file needed, IMO.

I think we could add a NEWS entry about the overall performance improvement in the last pull request.

I'm sharing two flame graphs, which show the ratios between the actual disk writes and the serialization/deserialization logic:

Sure, let me measure everything again tomorrow. Thanks!

modules/diskq/qdisk.c

kira-syslogng · 2021-08-03T09:24:23Z

Build FAILURE

kira-syslogng · 2021-08-03T10:49:01Z

Build SUCCESS

modules/diskq/logqueue-disk.c

modules/diskq/qdisk.c

kira-syslogng · 2021-08-04T09:24:08Z

Build SUCCESS

alltilla · 2021-08-05T10:50:07Z

Added the hint for needing serialized message.

MrAnno · 2021-08-05T10:55:58Z

@kira-syslogng do stresstest

kira-syslogng · 2021-08-05T11:13:17Z

Build SUCCESS

kira-syslogng · 2021-08-05T11:23:55Z

Kira-stress-test: Build SUCCESS

modules/diskq/qdisk.h

MrAnno · 2021-08-05T12:49:07Z

modules/diskq/logqueue-disk.c

  gboolean consumed = FALSE;

  if (qdisk_started(self->qdisk) && qdisk_is_space_avail(self->qdisk, 64))
    {
      ScratchBuffersMarker marker;
      GString *write_serialized = scratch_buffers_alloc_and_mark(&marker);

-      sa = serialize_string_archive_new(write_serialized);
-      log_msg_serialize(msg, sa, options->compaction ? LMSF_COMPACTION : 0);
+      if (!qdisk_serialize_msg(self->qdisk, msg, write_serialized))


qdisk: move serialization to qdisk is not only a move (refactor) commit, you also fixed the error handling of log_msg_serialize().

modules/diskq/qdisk.c

modules/diskq/logqueue-disk.h

modules/diskq/logqueue-disk.c

modules/diskq/logqueue-disk-non-reliable.c

MrAnno · 2021-08-05T13:56:19Z

All of my review notes are based on the ways of how the serialization logic was moved out from the lock.

The previous interface looks like this:

I think it's really not okay to change the signature of push_tail() in LogQueueDisk, because the existence of those function pointers in the struct is just some inheritance trickery that makes it possible to lock the whole data structure in the top-level abstract class easily.
In reality, those function pointers should have the exact same signature as LogQueue has.

Why don't we move the locks where they actually belong?
If I'm not mistaken, that would resolve all of the above issues.
I think we could remove lock/unlock calls from LogQueueDisk, move them to where they are actually needed/used (LogQueueDiskReliable and LogQueueDiskNonReliable).

We may also get rid of the 2 protected methods of LogQueueDisk: write_message() and read_message() (they look weird anyway together with push_tail and pop_head).

This way, message serialization can be done as a separate unlocked step in the non-reliable and reliable disk buffer, and you could also implement the non-reliable serialization hint without polluting LogQueueDisk with something that only makes sense in the non-reliable disk-buffer implementation.

Signed-off-by: Attila Szakacs <[email protected]>

alltilla · 2021-08-06T09:47:29Z

@MrAnno Thanks, I implemented your suggestion. The old implementation is available at: https://github.com/alltilla/syslog-ng/commits/diskq-perf-serialize-outside-lock-orig if for some reason it will be needed.

Signed-off-by: Attila Szakacs <[email protected]>

…ll() Signed-off-by: Attila Szakacs <[email protected]>

Signed-off-by: Attila Szakacs <[email protected]>

kira-syslogng · 2021-08-06T10:13:08Z

Build SUCCESS

alltilla · 2021-08-06T10:29:34Z

@kira-syslogng do stresstest

kira-syslogng · 2021-08-06T10:59:50Z

Kira-stress-test: Build SUCCESS

MrAnno

I think the refactor was a really good direction. Now that locks are closer to the actual implementation, we already see additional places where those locks are not necessary.

A few lines of code duplication was added as a result of the refactor/inheritance fix, but further refactor rounds will be much easier upon this work than on the original code IMHO.

I think only one of my notes should be fixed in this PR (the accidental change of the disk-buffer file's magic numbers).

modules/diskq/logqueue-disk-reliable.c

modules/diskq/logqueue-disk.c

modules/diskq/logqueue-disk-non-reliable.c

modules/diskq/logqueue-disk-reliable.c

modules/diskq/logqueue-disk.c

modules/diskq/logqueue-disk-non-reliable.c

Kokan

Does this version has the same performance figures as the previous proposed change ?
Have you measured that only the refactor part had any performance difference ?

modules/diskq/logqueue-disk-non-reliable.c

modules/diskq/qdisk.c

Signed-off-by: Attila Szakacs <[email protected]>

Just for the sake of symmetry. Signed-off-by: Attila Szakacs <[email protected]>

The serialized message now already has the guint32 record length in its beginning, so we do not need to make an adjustment in is_space_avail(). There are 2 other places where qdisk_is_space_avail() is used: * LogQueueDiskNonReliable::_has_movable_message(): It is a guess with a relatively high size, so we do not need to adjust it. * LogQueueDisk::log_queue_disk_write_message(): It will be fixed in one of the following commits. Signed-off-by: Attila Szakacs <[email protected]>

This functions does 3 things: 1. Does some preliminary check on QDisk. 2. Serializes the message. 3. Writes the message to the QDisk. Serializing and writing to disk are expensive actions. We are doing both, while holding the LogQueue::lock. We do not need to hold the lock while serializing. In order to move the serialization outside the lock, we need more control, which cannot be done with this common function. This commit only moves the function to the descendant classes, we will implement our class specific behavior in the following commits. Signed-off-by: Attila Szakacs <[email protected]>

…il() This commit also fixes the available space checking, mentioned in a169e331. Signed-off-by: Attila Szakacs <[email protected]>

…message_to_disk() The free space is checked in qdisk_push_tail(), it is unnecessary to do it twice. Signed-off-by: Attila Szakacs <[email protected]>

Signed-off-by: Attila Szakacs <[email protected]>

…h_tail() Signed-off-by: Attila Szakacs <[email protected]>

alltilla · 2021-08-09T09:27:02Z

@Kokan

Does this version has the same performance figures as the previous proposed change ?

Yes.

Have you measured that only the refactor part had any performance difference ?

No, I can do so, if you would like me to.

kira-syslogng · 2021-08-09T09:46:58Z

Build SUCCESS

MrAnno · 2021-08-09T12:24:50Z

@kira-syslogng do stresstest

kira-syslogng · 2021-08-09T12:53:43Z

Kira-stress-test: Build SUCCESS

MrAnno

Thank you

Kokan · 2021-08-09T12:59:41Z

No, I can do so, if you would like me to.

Not needed, I was just curios if we have the data.

MrAnno self-requested a review August 2, 2021 14:55

Barkodcz reviewed Aug 2, 2021

View reviewed changes

modules/diskq/logqueue-disk-non-reliable.c Outdated Show resolved Hide resolved

alltilla commented Aug 2, 2021

View reviewed changes

modules/diskq/qdisk.c Outdated Show resolved Hide resolved

alltilla force-pushed the diskq-perf-serialize-outside-lock branch from 316c17d to 5b1294a Compare August 3, 2021 09:03

alltilla force-pushed the diskq-perf-serialize-outside-lock branch from 5b1294a to 350b91a Compare August 3, 2021 10:24

Kokan reviewed Aug 4, 2021

View reviewed changes

modules/diskq/logqueue-disk.c Outdated Show resolved Hide resolved

modules/diskq/qdisk.c Outdated Show resolved Hide resolved

modules/diskq/qdisk.c Outdated Show resolved Hide resolved

modules/diskq/qdisk.c Outdated Show resolved Hide resolved

alltilla force-pushed the diskq-perf-serialize-outside-lock branch 5 times, most recently from acaef7f to a028825 Compare August 4, 2021 09:02

MrAnno reviewed Aug 5, 2021

View reviewed changes

logqueue-disk: fix inheritance of get_length()

d69a71f

Signed-off-by: Attila Szakacs <[email protected]>

alltilla force-pushed the diskq-perf-serialize-outside-lock branch from 3718a0f to 1c9060c Compare August 6, 2021 09:46

alltilla added 4 commits August 6, 2021 11:50

logqueue-disk: fix inheritance of ack_backlog()

4890f21

Signed-off-by: Attila Szakacs <[email protected]>

logqueue-disk: fix inheritance of push_head()

2085fcb

Signed-off-by: Attila Szakacs <[email protected]>

logqueue-disk: fix inheritance of rewind_backlog() & rewind_backlog_a…

a84003e

…ll() Signed-off-by: Attila Szakacs <[email protected]>

logqueue-disk: fix inheritance of destructor

76d7050

Signed-off-by: Attila Szakacs <[email protected]>

logqueue-disk: fix inheritance of pop_head()

8001050

Signed-off-by: Attila Szakacs <[email protected]>

alltilla force-pushed the diskq-perf-serialize-outside-lock branch from 1c9060c to 92110da Compare August 6, 2021 09:52

MrAnno reviewed Aug 7, 2021

View reviewed changes

MrAnno reviewed Aug 8, 2021

View reviewed changes

modules/diskq/logqueue-disk-non-reliable.c Outdated Show resolved Hide resolved

MrAnno reviewed Aug 8, 2021

View reviewed changes

modules/diskq/logqueue-disk-non-reliable.c Outdated Show resolved Hide resolved

Kokan reviewed Aug 9, 2021

View reviewed changes

modules/diskq/logqueue-disk-non-reliable.c Outdated Show resolved Hide resolved

modules/diskq/qdisk.c Show resolved Hide resolved

alltilla added 12 commits August 9, 2021 11:22

logqueue-disk: fix inheritance of push_tail()

90b54a0

Signed-off-by: Attila Szakacs <[email protected]>

logqueue-disk-reliable: refactor virtual function setting

067bf9e

Signed-off-by: Attila Szakacs <[email protected]>

logqueue-disk-non-reliable: refactor virtual function setting

7296681

Signed-off-by: Attila Szakacs <[email protected]>

qdisk: move initialization to constructor

ae625b6

Signed-off-by: Attila Szakacs <[email protected]>

qdisk: move serialization to qdisk

529bd0f

Signed-off-by: Attila Szakacs <[email protected]>

qdisk: move deserializaton to qdisk

603056d

Just for the sake of symmetry. Signed-off-by: Attila Szakacs <[email protected]>

logqueue-disk-reliable: serialize message outside the lock in push_ta…

9e86b53

…il() This commit also fixes the available space checking, mentioned in a169e331. Signed-off-by: Attila Szakacs <[email protected]>

logqueue-disk-(non-)reliable: do not check available space in _write_…

c0c5196

…message_to_disk() The free space is checked in qdisk_push_tail(), it is unnecessary to do it twice. Signed-off-by: Attila Szakacs <[email protected]>

qdisk: check if QDisk is started in push_tail()

4359d84

Signed-off-by: Attila Szakacs <[email protected]>

logqueue-disk-non-reliable: serialize message outside the lock in pus…

a80ef51

…h_tail() Signed-off-by: Attila Szakacs <[email protected]>

alltilla force-pushed the diskq-perf-serialize-outside-lock branch from 92110da to a80ef51 Compare August 9, 2021 09:23

MrAnno approved these changes Aug 9, 2021

View reviewed changes

Kokan approved these changes Aug 9, 2021

View reviewed changes

Kokan merged commit f1387d0 into syslog-ng:master Aug 9, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

logqueue-disk: serialize outside of the lock in the source threads #3746

logqueue-disk: serialize outside of the lock in the source threads #3746

alltilla commented Aug 2, 2021 •

edited

Loading

MrAnno commented Aug 2, 2021 •

edited

Loading

kira-syslogng commented Aug 2, 2021

alltilla commented Aug 2, 2021

kira-syslogng commented Aug 3, 2021

kira-syslogng commented Aug 3, 2021

kira-syslogng commented Aug 4, 2021

alltilla commented Aug 5, 2021

MrAnno commented Aug 5, 2021

kira-syslogng commented Aug 5, 2021

kira-syslogng commented Aug 5, 2021

MrAnno Aug 5, 2021

MrAnno commented Aug 5, 2021 •

edited

Loading

alltilla commented Aug 6, 2021

kira-syslogng commented Aug 6, 2021

alltilla commented Aug 6, 2021

kira-syslogng commented Aug 6, 2021

MrAnno left a comment •

edited

Loading

Kokan left a comment

alltilla commented Aug 9, 2021

kira-syslogng commented Aug 9, 2021

MrAnno commented Aug 9, 2021

kira-syslogng commented Aug 9, 2021

MrAnno left a comment

Kokan commented Aug 9, 2021

logqueue-disk: serialize outside of the lock in the source threads #3746

logqueue-disk: serialize outside of the lock in the source threads #3746

Conversation

alltilla commented Aug 2, 2021 • edited Loading

MrAnno commented Aug 2, 2021 • edited Loading

kira-syslogng commented Aug 2, 2021

alltilla commented Aug 2, 2021

kira-syslogng commented Aug 3, 2021

kira-syslogng commented Aug 3, 2021

kira-syslogng commented Aug 4, 2021

alltilla commented Aug 5, 2021

MrAnno commented Aug 5, 2021

kira-syslogng commented Aug 5, 2021

kira-syslogng commented Aug 5, 2021

MrAnno Aug 5, 2021

Choose a reason for hiding this comment

MrAnno commented Aug 5, 2021 • edited Loading

alltilla commented Aug 6, 2021

kira-syslogng commented Aug 6, 2021

alltilla commented Aug 6, 2021

kira-syslogng commented Aug 6, 2021

MrAnno left a comment • edited Loading

Choose a reason for hiding this comment

Kokan left a comment

Choose a reason for hiding this comment

alltilla commented Aug 9, 2021

kira-syslogng commented Aug 9, 2021

MrAnno commented Aug 9, 2021

kira-syslogng commented Aug 9, 2021

MrAnno left a comment

Choose a reason for hiding this comment

Kokan commented Aug 9, 2021

alltilla commented Aug 2, 2021 •

edited

Loading

MrAnno commented Aug 2, 2021 •

edited

Loading

MrAnno commented Aug 5, 2021 •

edited

Loading

MrAnno left a comment •

edited

Loading