<div dir="ltr"><br><br><div class="gmail_quote"><div dir="ltr">On Tue, Aug 21, 2018 at 10:13 AM Pranith Kumar Karampuri <<a href="mailto:pkarampu@redhat.com">pkarampu@redhat.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><br><br><div class="gmail_quote"><div dir="ltr">On Mon, Aug 20, 2018 at 3:20 PM Hu Bert <<a href="mailto:revirii@googlemail.com" target="_blank">revirii@googlemail.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Regarding hardware the machines are identical. Intel Xeon E5-1650 v3<br>
Hexa-Core; 64 GB DDR4 ECC; Dell PERC H330 8 Port SAS/SATA 12 GBit/s<br>
RAID Controller; operating system running on a raid1, then 4 disks<br>
(JBOD) as bricks.<br>
<br>
Ok, i ran perf for a few seconds.<br>
<br>
------------------------<br>
perf record --call-graph=dwarf -p 7897 -o<br>
/tmp/perf.gluster11.bricksdd1.out<br>
^C[ perf record: Woken up 378 times to write data ]<br>
Warning:<br>
Processed 83690 events and lost 96 chunks!<br>
<br>
Check IO/CPU overload!<br>
<br>
[ perf record: Captured and wrote 423.087 MB<br>
/tmp/perf.gluster11.bricksdd1.out (51744 samples) ]<br>
------------------------<br>
<br>
I copied a couple of lines:<br>
<br>
+ 8.10% 0.00% glusteriotwr22 [unknown] [k]<br>
0xffffffffffffffff<br>
+ 8.10% 0.00% glusteriotwr22 [kernel.kallsyms] [k] iterate_dir<br>
+ 8.10% 0.00% glusteriotwr22 [kernel.kallsyms] [k] sys_getdents<br>
+ 8.10% 0.00% glusteriotwr22 [kernel.kallsyms] [k] filldir<br>
+ 8.10% 0.00% glusteriotwr22 [kernel.kallsyms] [k] do_syscall_64<br>
+ 8.10% 0.00% glusteriotwr22 [kernel.kallsyms] [k]<br>
entry_SYSCALL_64_after_swapgs<br>
+ 8.10% 0.00% glusteriotwr22 <a href="http://libc-2.24.so" rel="noreferrer" target="_blank">libc-2.24.so</a> [.]<br>
0xffff80c60db8ef2b<br>
+ 8.10% 0.00% glusteriotwr22 <a href="http://libc-2.24.so" rel="noreferrer" target="_blank">libc-2.24.so</a> [.] readdir64<br>
+ 8.10% 0.00% glusteriotwr22 index.so [.]<br>
0xffff80c6192a1888<br>
+ 8.10% 0.04% glusteriotwr22 [kernel.kallsyms] [k]<br>
ext4_htree_fill_tree<br>
+ 8.10% 0.00% glusteriotwr22 [kernel.kallsyms] [k] ext4_readdir<br>
+ 7.95% 0.12% glusteriotwr22 [kernel.kallsyms] [k]<br>
htree_dirblock_to_tree<br>
+ 5.78% 0.96% glusteriotwr22 [kernel.kallsyms] [k]<br>
__ext4_read_dirblock<br>
+ 4.80% 0.02% glusteriotwr22 [kernel.kallsyms] [k] ext4_bread<br>
+ 4.78% 0.04% glusteriotwr22 [kernel.kallsyms] [k] ext4_getblk<br>
+ 4.72% 0.02% glusteriotwr22 [kernel.kallsyms] [k] __getblk_gfp<br>
+ 4.57% 0.00% glusteriotwr3 [unknown] [k]<br>
0xffffffffffffffff<br>
+ 4.55% 0.00% glusteriotwr3 [kernel.kallsyms] [k] do_syscall_64<br>
<br>
Do you need different or additional information?<br></blockquote><div><br></div><div>This looks like there are lot of readdirs going on which is different from what we observed earlier, how many seconds did you do perf record for? Will it be possible for you to do this for some more time? may be a minute? Just want to be sure that the data actually represents what we are observing.<br></div></div></div></blockquote><div><br></div><div>I found one code path which on lookup does readdirs. Could you give me the output of ls -l <brick-path>/.glusterfs/indices/xattrop on all the three bricks? It can probably give a correlation to see if it is indeed the same issue or not.<br></div><div> </div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><div class="gmail_quote"><div></div><div> </div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<br>
<br>
2018-08-20 11:20 GMT+02:00 Pranith Kumar Karampuri <<a href="mailto:pkarampu@redhat.com" target="_blank">pkarampu@redhat.com</a>>:<br>
> Even the brick which doesn't have high CPU seems to have same number of<br>
> lookups, so that's not it.<br>
> Is there any difference at all between the machines which have high CPU vs<br>
> low CPU?<br>
> I think the only other thing I would do is to install perf tools and try to<br>
> figure out the call-graph which is leading to so much CPU<br>
><br>
> This affects performance of the brick I think, so you may have to do it<br>
> quickly and for less time.<br>
><br>
> perf record --call-graph=dwarf -p <brick-pid> -o </path/to/output><br>
> then<br>
> perf report -i </path/to/output/given/in/the/previous/command><br>
><br>
><br>
> On Mon, Aug 20, 2018 at 2:40 PM Hu Bert <<a href="mailto:revirii@googlemail.com" target="_blank">revirii@googlemail.com</a>> wrote:<br>
>><br>
>> gluster volume heal shared info | grep -i number<br>
>> Number of entries: 0<br>
>> Number of entries: 0<br>
>> Number of entries: 0<br>
>> Number of entries: 0<br>
>> Number of entries: 0<br>
>> Number of entries: 0<br>
>> Number of entries: 0<br>
>> Number of entries: 0<br>
>> Number of entries: 0<br>
>> Number of entries: 0<br>
>> Number of entries: 0<br>
>> Number of entries: 0<br>
>><br>
>> Looks good to me.<br>
>><br>
>><br>
>> 2018-08-20 10:51 GMT+02:00 Pranith Kumar Karampuri <<a href="mailto:pkarampu@redhat.com" target="_blank">pkarampu@redhat.com</a>>:<br>
>> > There are a lot of Lookup operations in the system. But I am not able to<br>
>> > find why. Could you check the output of<br>
>> ><br>
>> > # gluster volume heal <volname> info | grep -i number<br>
>> ><br>
>> > it should print all zeros.<br>
>> ><br>
>> > On Fri, Aug 17, 2018 at 1:49 PM Hu Bert <<a href="mailto:revirii@googlemail.com" target="_blank">revirii@googlemail.com</a>> wrote:<br>
>> >><br>
>> >> I don't know what you exactly mean with workload, but the main<br>
>> >> function of the volume is storing (incl. writing, reading) images<br>
>> >> (from hundreds of bytes up to 30 MBs, overall ~7TB). The work is done<br>
>> >> by apache tomcat servers writing to / reading from the volume. Besides<br>
>> >> images there are some text files and binaries that are stored on the<br>
>> >> volume and get updated regularly (every x hours); we'll try to migrate<br>
>> >> the latter ones to local storage asap.<br>
>> >><br>
>> >> Interestingly it's only one process (and its threads) of the same<br>
>> >> brick on 2 of the gluster servers that consumes the CPU.<br>
>> >><br>
>> >> gluster11: bricksdd1; not healed; full CPU<br>
>> >> gluster12: bricksdd1; got healed; normal CPU<br>
>> >> gluster13: bricksdd1; got healed; full CPU<br>
>> >><br>
>> >> Besides: performance during heal (e.g. gluster12, bricksdd1) was way<br>
>> >> better than it is now. I've attached 2 pngs showing the differing cpu<br>
>> >> usage of last week before/after heal.<br>
>> >><br>
>> >> 2018-08-17 9:30 GMT+02:00 Pranith Kumar Karampuri<br>
>> >> <<a href="mailto:pkarampu@redhat.com" target="_blank">pkarampu@redhat.com</a>>:<br>
>> >> > There seems to be too many lookup operations compared to any other<br>
>> >> > operations. What is the workload on the volume?<br>
>> >> ><br>
>> >> > On Fri, Aug 17, 2018 at 12:47 PM Hu Bert <<a href="mailto:revirii@googlemail.com" target="_blank">revirii@googlemail.com</a>><br>
>> >> > wrote:<br>
>> >> >><br>
>> >> >> i hope i did get it right.<br>
>> >> >><br>
>> >> >> gluster volume profile shared start<br>
>> >> >> wait 10 minutes<br>
>> >> >> gluster volume profile shared info<br>
>> >> >> gluster volume profile shared stop<br>
>> >> >><br>
>> >> >> If that's ok, i've attached the output of the info command.<br>
>> >> >><br>
>> >> >><br>
>> >> >> 2018-08-17 8:31 GMT+02:00 Pranith Kumar Karampuri<br>
>> >> >> <<a href="mailto:pkarampu@redhat.com" target="_blank">pkarampu@redhat.com</a>>:<br>
>> >> >> > Please do volume profile also for around 10 minutes when CPU% is<br>
>> >> >> > high.<br>
>> >> >> ><br>
>> >> >> > On Fri, Aug 17, 2018 at 11:56 AM Pranith Kumar Karampuri<br>
>> >> >> > <<a href="mailto:pkarampu@redhat.com" target="_blank">pkarampu@redhat.com</a>> wrote:<br>
>> >> >> >><br>
>> >> >> >> As per the output, all io-threads are using a lot of CPU. It is<br>
>> >> >> >> better<br>
>> >> >> >> to<br>
>> >> >> >> check what the volume profile is to see what is leading to so<br>
>> >> >> >> much<br>
>> >> >> >> work<br>
>> >> >> >> for<br>
>> >> >> >> io-threads. Please follow the documentation at<br>
>> >> >> >><br>
>> >> >> >><br>
>> >> >> >><br>
>> >> >> >> <a href="https://gluster.readthedocs.io/en/latest/Administrator%20Guide/Monitoring%20Workload/" rel="noreferrer" target="_blank">https://gluster.readthedocs.io/en/latest/Administrator%20Guide/Monitoring%20Workload/</a><br>
>> >> >> >> section: "<br>
>> >> >> >><br>
>> >> >> >> Running GlusterFS Volume Profile Command"<br>
>> >> >> >><br>
>> >> >> >> and attach output of "gluster volume profile info",<br>
>> >> >> >><br>
>> >> >> >> On Fri, Aug 17, 2018 at 11:24 AM Hu Bert <<a href="mailto:revirii@googlemail.com" target="_blank">revirii@googlemail.com</a>><br>
>> >> >> >> wrote:<br>
>> >> >> >>><br>
>> >> >> >>> Good morning,<br>
>> >> >> >>><br>
>> >> >> >>> i ran the command during 100% CPU usage and attached the file.<br>
>> >> >> >>> Hopefully it helps.<br>
>> >> >> >>><br>
>> >> >> >>> 2018-08-17 7:33 GMT+02:00 Pranith Kumar Karampuri<br>
>> >> >> >>> <<a href="mailto:pkarampu@redhat.com" target="_blank">pkarampu@redhat.com</a>>:<br>
>> >> >> >>> > Could you do the following on one of the nodes where you are<br>
>> >> >> >>> > observing<br>
>> >> >> >>> > high<br>
>> >> >> >>> > CPU usage and attach that file to this thread? We can find<br>
>> >> >> >>> > what<br>
>> >> >> >>> > threads/processes are leading to high usage. Do this for say<br>
>> >> >> >>> > 10<br>
>> >> >> >>> > minutes<br>
>> >> >> >>> > when<br>
>> >> >> >>> > you see the ~100% CPU.<br>
>> >> >> >>> ><br>
>> >> >> >>> > top -bHd 5 > /tmp/top.${HOSTNAME}.txt<br>
>> >> >> >>> ><br>
>> >> >> >>> > On Wed, Aug 15, 2018 at 2:37 PM Hu Bert<br>
>> >> >> >>> > <<a href="mailto:revirii@googlemail.com" target="_blank">revirii@googlemail.com</a>><br>
>> >> >> >>> > wrote:<br>
>> >> >> >>> >><br>
>> >> >> >>> >> Hello again :-)<br>
>> >> >> >>> >><br>
>> >> >> >>> >> The self heal must have finished as there are no log entries<br>
>> >> >> >>> >> in<br>
>> >> >> >>> >> glustershd.log files anymore. According to munin disk latency<br>
>> >> >> >>> >> (average<br>
>> >> >> >>> >> io wait) has gone down to 100 ms, and disk utilization has<br>
>> >> >> >>> >> gone<br>
>> >> >> >>> >> down<br>
>> >> >> >>> >> to ~60% - both on all servers and hard disks.<br>
>> >> >> >>> >><br>
>> >> >> >>> >> But now system load on 2 servers (which were in the good<br>
>> >> >> >>> >> state)<br>
>> >> >> >>> >> fluctuates between 60 and 100; the server with the formerly<br>
>> >> >> >>> >> failed<br>
>> >> >> >>> >> disk has a load of 20-30.I've uploaded some munin graphics of<br>
>> >> >> >>> >> the<br>
>> >> >> >>> >> cpu<br>
>> >> >> >>> >> usage:<br>
>> >> >> >>> >><br>
>> >> >> >>> >> <a href="https://abload.de/img/gluster11_cpu31d3a.png" rel="noreferrer" target="_blank">https://abload.de/img/gluster11_cpu31d3a.png</a><br>
>> >> >> >>> >> <a href="https://abload.de/img/gluster12_cpu8sem7.png" rel="noreferrer" target="_blank">https://abload.de/img/gluster12_cpu8sem7.png</a><br>
>> >> >> >>> >> <a href="https://abload.de/img/gluster13_cpud7eni.png" rel="noreferrer" target="_blank">https://abload.de/img/gluster13_cpud7eni.png</a><br>
>> >> >> >>> >><br>
>> >> >> >>> >> This can't be normal. 2 of the servers under heavy load and<br>
>> >> >> >>> >> one<br>
>> >> >> >>> >> not<br>
>> >> >> >>> >> that much. Does anyone have an explanation of this strange<br>
>> >> >> >>> >> behaviour?<br>
>> >> >> >>> >><br>
>> >> >> >>> >><br>
>> >> >> >>> >> Thx :-)<br>
>> >> >> >>> >><br>
>> >> >> >>> >> 2018-08-14 9:37 GMT+02:00 Hu Bert <<a href="mailto:revirii@googlemail.com" target="_blank">revirii@googlemail.com</a>>:<br>
>> >> >> >>> >> > Hi there,<br>
>> >> >> >>> >> ><br>
>> >> >> >>> >> > well, it seems the heal has finally finished. Couldn't<br>
>> >> >> >>> >> > see/find<br>
>> >> >> >>> >> > any<br>
>> >> >> >>> >> > related log message; is there such a message in a specific<br>
>> >> >> >>> >> > log<br>
>> >> >> >>> >> > file?<br>
>> >> >> >>> >> ><br>
>> >> >> >>> >> > But i see the same behaviour when the last heal finished:<br>
>> >> >> >>> >> > all<br>
>> >> >> >>> >> > CPU<br>
>> >> >> >>> >> > cores are consumed by brick processes; not only by the<br>
>> >> >> >>> >> > formerly<br>
>> >> >> >>> >> > failed<br>
>> >> >> >>> >> > bricksdd1, but by all 4 brick processes (and their<br>
>> >> >> >>> >> > threads).<br>
>> >> >> >>> >> > Load<br>
>> >> >> >>> >> > goes<br>
>> >> >> >>> >> > up to > 100 on the 2 servers with the not-failed brick, and<br>
>> >> >> >>> >> > glustershd.log gets filled with a lot of entries. Load on<br>
>> >> >> >>> >> > the<br>
>> >> >> >>> >> > server<br>
>> >> >> >>> >> > with the then failed brick not that high, but still ~60.<br>
>> >> >> >>> >> ><br>
>> >> >> >>> >> > Is this behaviour normal? Is there some post-heal after a<br>
>> >> >> >>> >> > heal<br>
>> >> >> >>> >> > has<br>
>> >> >> >>> >> > finished?<br>
>> >> >> >>> >> ><br>
>> >> >> >>> >> > thx in advance :-)<br>
>> >> >> >>> ><br>
>> >> >> >>> ><br>
>> >> >> >>> ><br>
>> >> >> >>> > --<br>
>> >> >> >>> > Pranith<br>
>> >> >> >><br>
>> >> >> >><br>
>> >> >> >><br>
>> >> >> >> --<br>
>> >> >> >> Pranith<br>
>> >> >> ><br>
>> >> >> ><br>
>> >> >> ><br>
>> >> >> > --<br>
>> >> >> > Pranith<br>
>> >> ><br>
>> >> ><br>
>> >> ><br>
>> >> > --<br>
>> >> > Pranith<br>
>> ><br>
>> ><br>
>> ><br>
>> > --<br>
>> > Pranith<br>
><br>
><br>
><br>
> --<br>
> Pranith<br>
</blockquote></div><br clear="all"><br>-- <br><div dir="ltr" class="m_-221844135450245192m_-887529918622478586gmail_signature" data-smartmail="gmail_signature"><div dir="ltr">Pranith<br></div></div></div>
</blockquote></div><br clear="all"><br>-- <br><div dir="ltr" class="gmail_signature" data-smartmail="gmail_signature"><div dir="ltr">Pranith<br></div></div></div>