<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40">
<head>
<meta http-equiv="Content-Type" content="text/html; charset=koi8-r">
<meta name="Generator" content="Microsoft Word 15 (filtered medium)">
<style><!--
/* Font Definitions */
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
@font-face
{font-family:"MS PGothic";
panose-1:2 11 6 0 7 2 5 8 2 4;}
@font-face
{font-family:"\@MS PGothic";}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0cm;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri",sans-serif;
mso-fareast-language:EN-US;}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:#0563C1;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:#954F72;
text-decoration:underline;}
pre
{mso-style-priority:99;
mso-style-link:"HTML Vorformatiert Zchn";
margin:0cm;
margin-bottom:.0001pt;
font-size:10.0pt;
font-family:"Courier New";}
p.msonormal0, li.msonormal0, div.msonormal0
{mso-style-name:msonormal;
mso-margin-top-alt:auto;
margin-right:0cm;
mso-margin-bottom-alt:auto;
margin-left:0cm;
font-size:12.0pt;
font-family:"MS PGothic",sans-serif;
mso-fareast-language:JA;}
span.E-MailFormatvorlage18
{mso-style-type:personal;
font-family:"Calibri",sans-serif;
color:windowtext;}
span.E-MailFormatvorlage19
{mso-style-type:personal-reply;
font-family:"Calibri",sans-serif;
color:#1F497D;}
span.HTMLVorformatiertZchn
{mso-style-name:"HTML Vorformatiert Zchn";
mso-style-priority:99;
mso-style-link:"HTML Vorformatiert";
font-family:"Courier New";}
.MsoChpDefault
{mso-style-type:export-only;
font-size:10.0pt;}
@page WordSection1
{size:612.0pt 792.0pt;
margin:70.85pt 70.85pt 2.0cm 70.85pt;}
div.WordSection1
{page:WordSection1;}
--></style><!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]-->
</head>
<body lang="DE" link="#0563C1" vlink="#954F72">
<div class="WordSection1">
<p class="MsoNormal"><span lang="EN-US" style="color:#1F497D">Hi,<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US" style="color:#1F497D"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US" style="color:#1F497D">An update: The version I’m using (SLES 15 SP6 systemd-254.24) spends most of the time in fstat() cals, and I really wonder what’s going on there (say there are fewer than 20 files to process):<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US" style="color:#1F497D"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US" style="color:#1F497D">A perf example:<o:p></o:p></span></p>
<div style="mso-element:para-border-div;border:solid #CCCCCC 1.0pt;padding:6.0pt 6.0pt 6.0pt 6.0pt;background:#EFEFEF">
<pre style="background:#EFEFEF;border:none;padding:0cm"><o:p> </o:p></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm"><span lang="EN-US">41245567 % time seconds usecs/call calls errors syscall<o:p></o:p></span></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm"><span lang="EN-US">41245568 ------ ----------- ----------- --------- --------- ----------------<o:p></o:p></span></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm"><span lang="EN-US">41245569 99.94 64.453476 1 41230003 fstat<o:p></o:p></span></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm"><span lang="EN-US">41245570 0.04 0.023192 1 14234 write<o:p></o:p></span></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm"><span lang="EN-US">41245571 0.01 0.007399 29 253 munmap<o:p></o:p></span></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm"><span lang="EN-US">41245572 0.00 0.002771 6 432 mmap<o:p></o:p></span></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm"><span lang="EN-US">41245573 0.00 0.000908 5 166 17 openat<o:p></o:p></span></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm"><span lang="EN-US">41245574 0.00 0.000549 2 200 fcntl<o:p></o:p></span></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm"><span lang="EN-US">41245575 0.00 0.000528 5 103 fstatfs<o:p></o:p></span></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm"><span lang="EN-US">41245576 0.00 0.000262 8 32 mprotect<o:p></o:p></span></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm"><span lang="EN-US">41245577 0.00 0.000120 2 49 close<o:p></o:p></span></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm"><span lang="EN-US">41245578 0.00 0.000112 3 35 read<o:p></o:p></span></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm"><span lang="EN-US">41245579 0.00 0.000033 2 14 getrandom<o:p></o:p></span></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm"><span lang="EN-US">41245580 0.00 0.000016 4 4 brk<o:p></o:p></span></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm"><span lang="EN-US">41245581 0.00 0.000012 6 2 1 statfs<o:p></o:p></span></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm"><span lang="EN-US">41245582 0.00 0.000011 1 6 4 prctl<o:p></o:p></span></pre>
<pre style="background:#EFEFEF;border:none;padding:0cm">41245583 0.00 0.000011 1 6 getdents64<o:p></o:p></pre>
</div>
<p class="MsoNormal"><span lang="EN-US" style="color:#1F497D">…<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US" style="color:#1F497D"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US" style="color:#1F497D">So fstat is called 41 million times. Probably more often than the whole journal has blocks…<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US" style="color:#1F497D"><o:p> </o:p></span></p>
<div>
<p class="MsoNormal"><span lang="EN-US" style="color:#1F497D">Kind regards,<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US" style="color:#1F497D">Ulrich Windl<o:p></o:p></span></p>
</div>
<p class="MsoNormal"><span lang="EN-US" style="color:#1F497D"><o:p> </o:p></span></p>
<div style="border:none;border-left:solid blue 1.5pt;padding:0cm 0cm 0cm 4.0pt">
<div>
<div style="border:none;border-top:solid #E1E1E1 1.0pt;padding:3.0pt 0cm 0cm 0cm">
<p class="MsoNormal"><b><span style="mso-fareast-language:JA">From:</span></b><span style="mso-fareast-language:JA"> systemd-devel <systemd-devel-bounces@lists.freedesktop.org>
<b>On Behalf Of </b>Windl, Ulrich<br>
<b>Sent:</b> Wednesday, April 9, 2025 11:48 AM<br>
<b>To:</b> systemd-devel@lists.freedesktop.org<br>
<b>Subject:</b> [EXT] [systemd-devel] slowness reading persistent journal<o:p></o:p></span></p>
</div>
</div>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><span lang="EN-US">Hi!<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">In SLES15 SP6 (systemd-254.24-150600.4.28.1.x86_64) I noticed that collecting logs took quite long, so I checked.<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"># time journalctl |wc -l<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">2705448<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">real 2m23.008s<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">user 1m25.666s<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">sys 0m57.389s<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">The journal is persistent and it’s located on a BtrFS subvolume using a device that is provided by VMware from a high-performance SSD SAN storage:<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"># lsblk<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">NAME MAJ:MIN RM SIZE RO TYPE MOUNTPOINTS<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">sda 8:0 0 40G 0 disk<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US" style="font-family:"Arial",sans-serif">†</span><span lang="EN-US">€sda1 8:1 0 512M 0 part /boot/efi<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US" style="font-family:"Arial",sans-serif">†</span><span lang="EN-US">€sda2 8:2 0 21G 0 part /root<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"> /srv<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"> /usr/local<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"> /var<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"> /opt<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"> /tmp<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"> /boot/grub2/x86_64-efi<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"> /boot/grub2/i386-pc<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"> /.snapshots<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"> /<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US" style="font-family:"Arial",sans-serif">†</span><span lang="EN-US">€sda3 8:3 0 10.7G 0 part /home<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">„€sda4 8:4 0 7.8G 0 part [SWAP]<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"># hdparm -t /dev/sda2<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">/dev/sda2:<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">Timing buffered disk reads: 1680 MB in 3.00 seconds = 559.48 MB/sec<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"># hdparm -T /dev/sda2<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">/dev/sda2:<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">Timing cached reads: 18612 MB in 2.00 seconds = 9322.49 MB/sec<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">During boot this statistics had been logged:<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">System Journal (/var/log/journal/41d6ce7a6cfc467297b777b8d87f071d) is 2.0G, max 2.1G, 103.1M free.<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">Obvious question: Why is it so slow?<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">Kind regards,<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US">Ulrich Windl<o:p></o:p></span></p>
<p class="MsoNormal"><span lang="EN-US"><o:p> </o:p></span></p>
</div>
</div>
</body>
</html>