Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Changed log lock from 'quick' to 'basic' because this is an I/O lock. #124

Merged
merged 1 commit into from Dec 3, 2019

Conversation

@rmetrich
Copy link
Contributor

rmetrich commented Nov 26, 2019

We cannot use a 'quick' lock (i.e. lock spinning on the CPU) for the log
lock because it can wait a lot on I/Os. Using a 'quick' lock leads to
eating the CPU for no good reason.

Example of 'pidstat' output when using various locks for log_lock:

  • 'quick' lock and slow log file system (tail -f on the log file on XFS on RHEL 8)

04:15:11 PM UID TGID TID %usr %system %CPU CPU Command
04:15:21 PM 998 16431 - 100.00 4.20 100.00 2 unbound
04:15:21 PM 998 - 16431 31.00 1.00 32.00 2 |__unbound
04:15:21 PM 998 - 16432 31.30 0.80 32.10 0 |__unbound
04:15:21 PM 998 - 16433 30.20 1.40 31.60 1 |__unbound
04:15:21 PM 998 - 16434 30.70 1.00 31.70 3 |__unbound

  • 'quick' lock and log file system being fast

04:15:40 PM UID TGID TID %usr %system %CPU CPU Command
04:15:50 PM 998 16431 - 10.00 1.60 11.60 1 unbound
04:15:50 PM 998 - 16431 2.50 0.50 3.00 1 |__unbound
04:15:50 PM 998 - 16432 2.30 0.40 2.70 3 |__unbound
04:15:50 PM 998 - 16433 2.70 0.30 3.00 0 |__unbound
04:15:50 PM 998 - 16434 2.60 0.40 3.00 2 |__unbound

  • 'basic' lock (this commit) and slow log file system (tail -f on the log file on XFS on RHEL 8)

04:29:48 PM UID TGID TID %usr %system %CPU CPU Command
04:29:58 PM 998 11632 - 7.10 14.10 21.20 3 unbound
04:29:58 PM 998 - 11632 1.70 3.20 4.90 3 |__unbound
04:29:58 PM 998 - 11633 1.60 3.30 4.90 1 |__unbound
04:29:58 PM 998 - 11634 2.00 4.10 6.10 1 |__unbound
04:29:58 PM 998 - 11635 1.90 3.50 5.40 1 |__unbound

We can see in the above example, when 'basic' lock is used, that CPU
isn't consumed when log file system is slow.

Another reproducer scenario: put the log file on a NFS share with 'sync'
option.

We cannot use a 'quick' lock (i.e. lock spinning on the CPU) for the log
lock because it can wait a lot on I/Os. Using a 'quick' lock leads to
eating the CPU for no good reason.

Example of 'pidstat' output when using various locks for log_lock:

- 'quick' lock and slow log file system (tail -f on the log file on XFS on RHEL 8)

04:15:11 PM   UID      TGID       TID    %usr %system    %CPU CPU  Command
04:15:21 PM   998     16431         -  100.00    4.20  100.00   2  unbound
04:15:21 PM   998         -     16431   31.00    1.00   32.00   2  |__unbound
04:15:21 PM   998         -     16432   31.30    0.80   32.10   0  |__unbound
04:15:21 PM   998         -     16433   30.20    1.40   31.60   1  |__unbound
04:15:21 PM   998         -     16434   30.70    1.00   31.70   3  |__unbound

- 'quick' lock and log file system being fast

04:15:40 PM   UID      TGID       TID    %usr %system   %CPU CPU  Command
04:15:50 PM   998     16431         -   10.00    1.60  11.60   1  unbound
04:15:50 PM   998         -     16431    2.50    0.50   3.00   1  |__unbound
04:15:50 PM   998         -     16432    2.30    0.40   2.70   3  |__unbound
04:15:50 PM   998         -     16433    2.70    0.30   3.00   0  |__unbound
04:15:50 PM   998         -     16434    2.60    0.40   3.00   2  |__unbound

- 'basic' lock (this commit) and slow log file system (tail -f on the log file on XFS on RHEL 8)

04:29:48 PM   UID      TGID       TID    %usr %system   %CPU CPU  Command
04:29:58 PM   998     11632         -    7.10   14.10  21.20   3  unbound
04:29:58 PM   998         -     11632    1.70    3.20   4.90   3  |__unbound
04:29:58 PM   998         -     11633    1.60    3.30   4.90   1  |__unbound
04:29:58 PM   998         -     11634    2.00    4.10   6.10   1  |__unbound
04:29:58 PM   998         -     11635    1.90    3.50   5.40   1  |__unbound

We can see in the above example, when 'basic' lock is used, that CPU
isn't consumed when log file system is slow.

Another reproducer scenario: put the log file on a NFS share with 'sync'
option.
Copy link
Member

wcawijngaards left a comment

Changes look good!

@wcawijngaards

This comment has been minimized.

Copy link
Member

wcawijngaards commented Dec 3, 2019

That look like it improves CPU usage, the lower CPU usage is nice for high throughput (and thus also slower log wait times I guess) situations, so I think this is a very good fix to have. Thanks for the measurements and the suggested fix!

@wcawijngaards wcawijngaards merged commit 4edb162 into NLnetLabs:master Dec 3, 2019
1 check passed
1 check passed
continuous-integration/travis-ci/pr The Travis CI build passed
Details
wcawijngaards added a commit that referenced this pull request Dec 3, 2019
- Merge pull request #124 from rmetrich: Changed log lock
  from 'quick' to 'basic' because this is an I/O lock.
@rmetrich

This comment has been minimized.

Copy link
Contributor Author

rmetrich commented Dec 3, 2019

Thank you, I appreciate. For your information, this was reported by one of Red Hat customers and I filed RHBZ https://bugzilla.redhat.com/show_bug.cgi?id=1775708 for that.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
2 participants
You can’t perform that action at this time.