1

Whenever I run journalctl, it runs astonishingly slowly. It often takes minutes or even hours to return results. I've experienced some other performance problems on the affected machine that seemed to be related to I/O-intensive applications; I recently replaced the SATA cable which improved performance but didn't completely fix the problem. I've run S.M.A.R.T. tests on all the drives and they come out okay, based on this list of "critical" attributes that predict disk failure.

Note that I will not have physical access to the affected machine for several months, unfortunately.

I ran journalctl -xn through strace -T as root; here's a sampling of the output:

fstatfs(23, {f_type=0x9123683e, f_bsize=4096, f_blocks=272871862, f_bfree=10246662, f_bavail=9257376, f_files=0, f_ffree=0, f_fsid={-1736151745, 782050752}, f_namelen=255, f_frsize=4096}) = 0 <0.000044>
open("/var/log/journal/40b4c4d188900ed4b228417f53bce3a8/system@000549d205557c7b-3bab3b9a8debeb5c.journal~", O_RDONLY|O_CLOEXEC) = 24 <0.000045>
fstat(24, {st_mode=S_IFREG|0640, st_size=67108864, ...}) = 0 <0.000044>
mmap(NULL, 4096, PROT_READ, MAP_SHARED, 24, 0) = 0x7fce771b7000 <0.000052>
mmap(NULL, 8388608, PROT_READ, MAP_SHARED, 24, 0) = 0x7fce6be4c000 <0.000101>
fstatfs(24, {f_type=0x9123683e, f_bsize=4096, f_blocks=272871862, f_bfree=10246681, f_bavail=9257367, f_files=0, f_ffree=0, f_fsid={-1736151745, 782050752}, f_namelen=255, f_frsize=4096}) = 0 <0.000044>
open("/var/log/journal/40b4c4d188900ed4b228417f53bce3a8/system@000549e2c7cdcf84-9d1738f7aa7e2bbb.journal~", O_RDONLY|O_CLOEXEC) = 25 <0.000040>
fstat(25, {st_mode=S_IFREG|0640, st_size=83886080, ...}) = 0 <0.000040>
mmap(NULL, 4096, PROT_READ, MAP_SHARED, 25, 0) = 0x7fce771b6000 <0.000177>
mmap(NULL, 8388608, PROT_READ, MAP_SHARED, 25, 0) = 0x7fce6b64c000 <0.000126>
fstatfs(25, {f_type=0x9123683e, f_bsize=4096, f_blocks=272871862, f_bfree=10246807, f_bavail=9257509, f_files=0, f_ffree=0, f_fsid={-1736151745, 782050752}, f_namelen=255, f_frsize=4096}) = 0 <0.000071>
open("/var/log/journal/40b4c4d188900ed4b228417f53bce3a8/system@00054a0d278bd396-a5f78900d1a76e3a.journal~", O_RDONLY|O_CLOEXEC) = 26 <0.000073>
fstat(26, {st_mode=S_IFREG|0640, st_size=67108864, ...}) = 0 <0.000046>
mmap(NULL, 4096, PROT_READ, MAP_SHARED, 26, 0) = 0x7fce771b5000 <0.554027>
mmap(NULL, 8388608, PROT_READ, MAP_SHARED, 26, 0) = 0x7fce6ae4c000 <0.000155>
fstatfs(26, {f_type=0x9123683e, f_bsize=4096, f_blocks=272871862, f_bfree=10248655, f_bavail=9257373, f_files=0, f_ffree=0, f_fsid={-1736151745, 782050752}, f_namelen=255, f_frsize=4096}) = 0 <0.000091>
open("/var/log/journal/40b4c4d188900ed4b228417f53bce3a8/user-5000@00054a0d2867ce5c-2c11c922477ad87d.journal~", O_RDONLY|O_CLOEXEC) = 27 <0.000082>
fstat(27, {st_mode=S_IFREG|0640, st_size=8388608, ...}) = 0 <0.000064>
mmap(NULL, 4096, PROT_READ, MAP_SHARED, 27, 0) = 0x7fce771b4000 <0.129685>
mmap(NULL, 8388608, PROT_READ, MAP_SHARED, 27, 0) = 0x7fce6a64c000 <0.000119>
fstatfs(27, {f_type=0x9123683e, f_bsize=4096, f_blocks=272871862, f_bfree=10245778, f_bavail=9256592, f_files=0, f_ffree=0, f_fsid={-1736151745, 782050752}, f_namelen=255, f_frsize=4096}) = 0 <0.000043>
open("/var/log/journal/40b4c4d188900ed4b228417f53bce3a8/system@00054a203119342d-9cc91adca322dda0.journal~", O_RDONLY|O_CLOEXEC) = 28 <0.000043>
fstat(28, {st_mode=S_IFREG|0640, st_size=109051904, ...}) = 0 <0.000047>
mmap(NULL, 4096, PROT_READ, MAP_SHARED, 28, 0) = 0x7fce771b3000 <2.106414>
mmap(NULL, 8388608, PROT_READ, MAP_SHARED, 28, 0) = 0x7fce69e4c000 <0.000099>
fstatfs(28, {f_type=0x9123683e, f_bsize=4096, f_blocks=272871862, f_bfree=10247093, f_bavail=9257207, f_files=0, f_ffree=0, f_fsid={-1736151745, 782050752}, f_namelen=255, f_frsize=4096}) = 0 <0.000037>
open("/var/log/journal/40b4c4d188900ed4b228417f53bce3a8/system@00054a25abc23b2b-87a21b1480ce83fc.journal~", O_RDONLY|O_CLOEXEC) = 29 <0.000039>
fstat(29, {st_mode=S_IFREG|0640, st_size=50331648, ...}) = 0 <0.000034>
mmap(NULL, 4096, PROT_READ, MAP_SHARED, 29, 0) = 0x7fce771b2000 <0.000043>
mmap(NULL, 8388608, PROT_READ, MAP_SHARED, 29, 0) = 0x7fce6964c000 <0.000026>
open("/dev/urandom", O_RDONLY|O_NOCTTY|O_CLOEXEC) = 30 <0.000019>
read(30, "_\f\327\367\310\220\344\23U\307\23N@\310\323\226", 16) = 16 <0.000010>
close(30)                               = 0 <0.000010>
open("/dev/urandom", O_RDONLY|O_NOCTTY|O_CLOEXEC) = 30 <0.000014>
read(30, "u\207\326\2360t\0T*\34\222\226\4\22\361w", 16) = 16 <0.000011>
close(30)                               = 0 <0.000010>
fstatfs(29, {f_type=0x9123683e, f_bsize=4096, f_blocks=272871862, f_bfree=10246938, f_bavail=9257024, f_files=0, f_ffree=0, f_fsid={-1736151745, 782050752}, f_namelen=255, f_frsize=4096}) = 0 <0.000015>
open("/var/log/journal/40b4c4d188900ed4b228417f53bce3a8/system@00054a300132019a-2f63039e261fecd4.journal~", O_RDONLY|O_CLOEXEC) = 30 <0.000014>
fstat(30, {st_mode=S_IFREG|0640, st_size=58720256, ...}) = 0 <0.000010>
mmap(NULL, 4096, PROT_READ, MAP_SHARED, 30, 0) = 0x7fce771b1000 <3.332606>

The process always seems to hang for a while on mmap() calls that look similar to the last one. I used dd if=/dev/zero of=testfile.tmp to benchmark disk I/O. When doing this I observed disk write hovering around 1000 M/s (+/- ~150 M/s most of the time), although it occasionally dropped down to 300 M/s or lower (going all the way down to ~70 M/s). When I killed it dd reported 15689293824 bytes (16 GB) copied, 174.361 s, 90.0 MB/s. Tellingly, when running the same test backwards (dd if=testfile.tmp of=/dev/null), the disk read performance as reported by iotop didn't get above 250 M/s, was almost always below 100 M/s, and was often below 50 M/s. Killing this second dd process produced 10573660160 bytes (11 GB) copied, 148.573 s, 71.2 MB/s.

Here's some more debugging information (note that these were run after I killed the journalctl -xn process):

% find /var/log/journal | wc -l
115
% uname -a
Linux steevie 4.9.0-0.bpo.5-amd64 #1 SMP Debian 4.9.65-3+deb9u2~bpo8+1 (2017-01-05) x86_64 GNU/Linux
% vmstat
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0 1495592 160420     80 4586516  199  179 15827  1391   15    8  7  5 37 51  0

Note that the filesystem is on a btrfs RAID1 array and one of the devices is inside a LUKS container (for historical reasons):

% sudo btrfs filesystem show /
Label: '[root]'  uuid: 06c6565d-af6c-4123-9e42-3b6281f164e6
        Total devices 4 FS bytes used 990.93GiB
        devid    2 size 931.47GiB used 931.47GiB path /dev/mapper/sda2_crypt
        devid    4 size 109.45GiB used 109.45GiB path /dev/sda6
        devid    5 size 109.45GiB used 109.45GiB path /dev/sdb6
        devid    6 size 931.47GiB used 931.47GiB path /dev/sdc2

% sudo btrfs device usage /
/dev/mapper/sda2_crypt, ID: 2
   Device size:           931.47GiB
   Device slack:              0.00B
   Data,RAID1:            917.50GiB
   Metadata,RAID1:         13.94GiB
   System,RAID1:           32.00MiB
   Unallocated:             1.02MiB

/dev/sda6, ID: 4
   Device size:           109.45GiB
   Device slack:              0.00B
   Data,RAID1:            102.51GiB
   Metadata,RAID1:          6.94GiB
   Unallocated:             1.00MiB

/dev/sdb6, ID: 5
   Device size:           109.45GiB
   Device slack:              0.00B
   Data,RAID1:            104.42GiB
   Metadata,RAID1:          5.00GiB
   System,RAID1:           32.00MiB
   Unallocated:             3.00MiB

/dev/sdc2, ID: 6
   Device size:           931.47GiB
   Device slack:              0.00B
   Data,RAID1:            927.47GiB
   Metadata,RAID1:          4.00GiB
   Unallocated:             1.02MiB

sda2_crypt here is misleading; it's actually backed by /dev/sdd2. /dev/sda and /dev/sdb are SSDs; /dev/sdc and /dev/sdd are HDDs.

I'm on Debian 8. Happy to post smartctl logs if needed, but they're kinda long which is why I'm omitting them at this point.

  • Are you sure it's the mmap() that's slow? It could also be the open() calls, or something else entirely. You can add options such as -t/-tt/-ttt and/or -T to get timing data. Your disk IO rates from dd don't account for things like opening files. – Andrew Henle Jan 20 '18 at 0:11
  • @AndrewHenle yeah, I watched the output in realtime and it was clearly paused on mmap(). if timing information would be helpful beyond that though, I'm happy to provide it. – strugee Jan 20 '18 at 0:38
  • 1
    Did the pause happen after it emitted the mmap() lines? If so, mmap() has already returned - note that there's a return value on all your mmap() lines. – Andrew Henle Jan 20 '18 at 15:54
  • @AndrewHenle ooo, nice catch. I'll edit the question to correct that. – strugee Jan 21 '18 at 23:07

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.