[Gluster-users] Gluter 3.12.12: performance during heal and in general
Hu Bert
revirii at googlemail.com
Tue Aug 21 06:10:51 UTC 2018
Good morning :-)
gluster11:
ls -l /gluster/bricksdd1/shared/.glusterfs/indices/xattrop/
total 0
---------- 1 root root 0 Aug 14 06:14
xattrop-006b65d8-9e81-4886-b380-89168ea079bd
gluster12:
ls -l /gluster/bricksdd1_new/shared/.glusterfs/indices/xattrop/
total 0
---------- 1 root root 0 Jul 17 11:24
xattrop-c7c6f765-ce17-4361-95fb-2fd7f31c7b82
gluster13:
ls -l /gluster/bricksdd1_new/shared/.glusterfs/indices/xattrop/
total 0
---------- 1 root root 0 Aug 16 07:54
xattrop-16b696a0-4214-4999-b277-0917c76c983e
And here's the output of 'perf ...' which ran almost a minute - file
grew pretty fast to a size of 17 GB and system load went up heavily.
Had to wait a while until load dropped :-)
fyi - load at the moment:
load gluster11: ~90
load gluster12: ~10
load gluster13: ~50
perf record --call-graph=dwarf -p 7897 -o /tmp/perf.gluster11.bricksdd1.out
[ perf record: Woken up 9837 times to write data ]
Warning:
Processed 2137218 events and lost 33446 chunks!
Check IO/CPU overload!
[ perf record: Captured and wrote 16576.374 MB
/tmp/perf.gluster11.bricksdd1.out (2047760 samples) ]
Here's an excerpt.
+ 1.93% 0.00% glusteriotwr0 [unknown] [k]
0xffffffffffffffff
+ 1.89% 0.00% glusteriotwr28 [unknown] [k]
0xffffffffffffffff
+ 1.86% 0.00% glusteriotwr15 [unknown] [k]
0xffffffffffffffff
+ 1.85% 0.00% glusteriotwr63 [unknown] [k]
0xffffffffffffffff
+ 1.83% 0.01% glusteriotwr0 [kernel.kallsyms] [k]
entry_SYSCALL_64_after_swapgs
+ 1.82% 0.00% glusteriotwr38 [unknown] [k]
0xffffffffffffffff
+ 1.82% 0.01% glusteriotwr28 [kernel.kallsyms] [k]
entry_SYSCALL_64_after_swapgs
+ 1.82% 0.00% glusteriotwr0 [kernel.kallsyms] [k] do_syscall_64
+ 1.81% 0.00% glusteriotwr28 [kernel.kallsyms] [k] do_syscall_64
+ 1.81% 0.00% glusteriotwr15 [kernel.kallsyms] [k]
entry_SYSCALL_64_after_swapgs
+ 1.81% 0.00% glusteriotwr36 [unknown] [k]
0xffffffffffffffff
+ 1.80% 0.00% glusteriotwr15 [kernel.kallsyms] [k] do_syscall_64
+ 1.78% 0.01% glusteriotwr63 [kernel.kallsyms] [k]
entry_SYSCALL_64_after_swapgs
+ 1.77% 0.00% glusteriotwr63 [kernel.kallsyms] [k] do_syscall_64
+ 1.75% 0.01% glusteriotwr38 [kernel.kallsyms] [k]
entry_SYSCALL_64_after_swapgs
+ 1.75% 0.00% glusteriotwr38 [kernel.kallsyms] [k] do_syscall_64
+ 1.74% 0.00% glusteriotwr17 [unknown] [k]
0xffffffffffffffff
+ 1.74% 0.00% glusteriotwr44 [unknown] [k]
0xffffffffffffffff
+ 1.73% 0.00% glusteriotwr6 [unknown] [k]
0xffffffffffffffff
+ 1.73% 0.00% glusteriotwr37 [unknown] [k]
0xffffffffffffffff
+ 1.73% 0.01% glusteriotwr36 [kernel.kallsyms] [k]
entry_SYSCALL_64_after_swapgs
+ 1.72% 0.00% glusteriotwr34 [unknown] [k]
0xffffffffffffffff
+ 1.72% 0.00% glusteriotwr36 [kernel.kallsyms] [k] do_syscall_64
+ 1.71% 0.00% glusteriotwr45 [unknown] [k]
0xffffffffffffffff
+ 1.70% 0.00% glusteriotwr7 [unknown] [k]
0xffffffffffffffff
+ 1.68% 0.00% glusteriotwr15 [kernel.kallsyms] [k] sys_getdents
+ 1.68% 0.00% glusteriotwr15 [kernel.kallsyms] [k] filldir
+ 1.68% 0.00% glusteriotwr15 libc-2.24.so [.]
0xffff80c60db8ef2b
+ 1.68% 0.00% glusteriotwr15 libc-2.24.so [.] readdir64
+ 1.68% 0.00% glusteriotwr15 index.so [.]
0xffff80c6192a1888
+ 1.68% 0.00% glusteriotwr15 [kernel.kallsyms] [k] iterate_dir
+ 1.68% 0.00% glusteriotwr15 [kernel.kallsyms] [k]
ext4_htree_fill_tree
+ 1.68% 0.00% glusteriotwr15 [kernel.kallsyms] [k] ext4_readdir
Or do you want to download the file /tmp/perf.gluster11.bricksdd1.out
and examine it yourself? If so i could send you a link.
2018-08-21 7:13 GMT+02:00 Pranith Kumar Karampuri <pkarampu at redhat.com>:
>
>
> On Tue, Aug 21, 2018 at 10:13 AM Pranith Kumar Karampuri
> <pkarampu at redhat.com> wrote:
>>
>>
>>
>> On Mon, Aug 20, 2018 at 3:20 PM Hu Bert <revirii at googlemail.com> wrote:
>>>
>>> Regarding hardware the machines are identical. Intel Xeon E5-1650 v3
>>> Hexa-Core; 64 GB DDR4 ECC; Dell PERC H330 8 Port SAS/SATA 12 GBit/s
>>> RAID Controller; operating system running on a raid1, then 4 disks
>>> (JBOD) as bricks.
>>>
>>> Ok, i ran perf for a few seconds.
>>>
>>> ------------------------
>>> perf record --call-graph=dwarf -p 7897 -o
>>> /tmp/perf.gluster11.bricksdd1.out
>>> ^C[ perf record: Woken up 378 times to write data ]
>>> Warning:
>>> Processed 83690 events and lost 96 chunks!
>>>
>>> Check IO/CPU overload!
>>>
>>> [ perf record: Captured and wrote 423.087 MB
>>> /tmp/perf.gluster11.bricksdd1.out (51744 samples) ]
>>> ------------------------
>>>
>>> I copied a couple of lines:
>>>
>>> + 8.10% 0.00% glusteriotwr22 [unknown] [k]
>>> 0xffffffffffffffff
>>> + 8.10% 0.00% glusteriotwr22 [kernel.kallsyms] [k]
>>> iterate_dir
>>> + 8.10% 0.00% glusteriotwr22 [kernel.kallsyms] [k]
>>> sys_getdents
>>> + 8.10% 0.00% glusteriotwr22 [kernel.kallsyms] [k] filldir
>>> + 8.10% 0.00% glusteriotwr22 [kernel.kallsyms] [k]
>>> do_syscall_64
>>> + 8.10% 0.00% glusteriotwr22 [kernel.kallsyms] [k]
>>> entry_SYSCALL_64_after_swapgs
>>> + 8.10% 0.00% glusteriotwr22 libc-2.24.so [.]
>>> 0xffff80c60db8ef2b
>>> + 8.10% 0.00% glusteriotwr22 libc-2.24.so [.]
>>> readdir64
>>> + 8.10% 0.00% glusteriotwr22 index.so [.]
>>> 0xffff80c6192a1888
>>> + 8.10% 0.04% glusteriotwr22 [kernel.kallsyms] [k]
>>> ext4_htree_fill_tree
>>> + 8.10% 0.00% glusteriotwr22 [kernel.kallsyms] [k]
>>> ext4_readdir
>>> + 7.95% 0.12% glusteriotwr22 [kernel.kallsyms] [k]
>>> htree_dirblock_to_tree
>>> + 5.78% 0.96% glusteriotwr22 [kernel.kallsyms] [k]
>>> __ext4_read_dirblock
>>> + 4.80% 0.02% glusteriotwr22 [kernel.kallsyms] [k]
>>> ext4_bread
>>> + 4.78% 0.04% glusteriotwr22 [kernel.kallsyms] [k]
>>> ext4_getblk
>>> + 4.72% 0.02% glusteriotwr22 [kernel.kallsyms] [k]
>>> __getblk_gfp
>>> + 4.57% 0.00% glusteriotwr3 [unknown] [k]
>>> 0xffffffffffffffff
>>> + 4.55% 0.00% glusteriotwr3 [kernel.kallsyms] [k]
>>> do_syscall_64
>>>
>>> Do you need different or additional information?
>>
>>
>> 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.
>
>
> 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.
>
>>
>>
>>>
>>>
>>>
>>> 2018-08-20 11:20 GMT+02:00 Pranith Kumar Karampuri <pkarampu at redhat.com>:
>>> > Even the brick which doesn't have high CPU seems to have same number of
>>> > lookups, so that's not it.
>>> > Is there any difference at all between the machines which have high CPU
>>> > vs
>>> > low CPU?
>>> > I think the only other thing I would do is to install perf tools and
>>> > try to
>>> > figure out the call-graph which is leading to so much CPU
>>> >
>>> > This affects performance of the brick I think, so you may have to do it
>>> > quickly and for less time.
>>> >
>>> > perf record --call-graph=dwarf -p <brick-pid> -o </path/to/output>
>>> > then
>>> > perf report -i </path/to/output/given/in/the/previous/command>
>>> >
>>> >
>>> > On Mon, Aug 20, 2018 at 2:40 PM Hu Bert <revirii at googlemail.com> wrote:
>>> >>
>>> >> gluster volume heal shared info | grep -i number
>>> >> Number of entries: 0
>>> >> Number of entries: 0
>>> >> Number of entries: 0
>>> >> Number of entries: 0
>>> >> Number of entries: 0
>>> >> Number of entries: 0
>>> >> Number of entries: 0
>>> >> Number of entries: 0
>>> >> Number of entries: 0
>>> >> Number of entries: 0
>>> >> Number of entries: 0
>>> >> Number of entries: 0
>>> >>
>>> >> Looks good to me.
>>> >>
>>> >>
>>> >> 2018-08-20 10:51 GMT+02:00 Pranith Kumar Karampuri
>>> >> <pkarampu at redhat.com>:
>>> >> > There are a lot of Lookup operations in the system. But I am not
>>> >> > able to
>>> >> > find why. Could you check the output of
>>> >> >
>>> >> > # gluster volume heal <volname> info | grep -i number
>>> >> >
>>> >> > it should print all zeros.
>>> >> >
>>> >> > On Fri, Aug 17, 2018 at 1:49 PM Hu Bert <revirii at googlemail.com>
>>> >> > wrote:
>>> >> >>
>>> >> >> I don't know what you exactly mean with workload, but the main
>>> >> >> function of the volume is storing (incl. writing, reading) images
>>> >> >> (from hundreds of bytes up to 30 MBs, overall ~7TB). The work is
>>> >> >> done
>>> >> >> by apache tomcat servers writing to / reading from the volume.
>>> >> >> Besides
>>> >> >> images there are some text files and binaries that are stored on
>>> >> >> the
>>> >> >> volume and get updated regularly (every x hours); we'll try to
>>> >> >> migrate
>>> >> >> the latter ones to local storage asap.
>>> >> >>
>>> >> >> Interestingly it's only one process (and its threads) of the same
>>> >> >> brick on 2 of the gluster servers that consumes the CPU.
>>> >> >>
>>> >> >> gluster11: bricksdd1; not healed; full CPU
>>> >> >> gluster12: bricksdd1; got healed; normal CPU
>>> >> >> gluster13: bricksdd1; got healed; full CPU
>>> >> >>
>>> >> >> Besides: performance during heal (e.g. gluster12, bricksdd1) was
>>> >> >> way
>>> >> >> better than it is now. I've attached 2 pngs showing the differing
>>> >> >> cpu
>>> >> >> usage of last week before/after heal.
>>> >> >>
>>> >> >> 2018-08-17 9:30 GMT+02:00 Pranith Kumar Karampuri
>>> >> >> <pkarampu at redhat.com>:
>>> >> >> > There seems to be too many lookup operations compared to any
>>> >> >> > other
>>> >> >> > operations. What is the workload on the volume?
>>> >> >> >
>>> >> >> > On Fri, Aug 17, 2018 at 12:47 PM Hu Bert <revirii at googlemail.com>
>>> >> >> > wrote:
>>> >> >> >>
>>> >> >> >> i hope i did get it right.
>>> >> >> >>
>>> >> >> >> gluster volume profile shared start
>>> >> >> >> wait 10 minutes
>>> >> >> >> gluster volume profile shared info
>>> >> >> >> gluster volume profile shared stop
>>> >> >> >>
>>> >> >> >> If that's ok, i've attached the output of the info command.
>>> >> >> >>
>>> >> >> >>
>>> >> >> >> 2018-08-17 8:31 GMT+02:00 Pranith Kumar Karampuri
>>> >> >> >> <pkarampu at redhat.com>:
>>> >> >> >> > Please do volume profile also for around 10 minutes when CPU%
>>> >> >> >> > is
>>> >> >> >> > high.
>>> >> >> >> >
>>> >> >> >> > On Fri, Aug 17, 2018 at 11:56 AM Pranith Kumar Karampuri
>>> >> >> >> > <pkarampu at redhat.com> wrote:
>>> >> >> >> >>
>>> >> >> >> >> As per the output, all io-threads are using a lot of CPU. It
>>> >> >> >> >> is
>>> >> >> >> >> better
>>> >> >> >> >> to
>>> >> >> >> >> check what the volume profile is to see what is leading to so
>>> >> >> >> >> much
>>> >> >> >> >> work
>>> >> >> >> >> for
>>> >> >> >> >> io-threads. Please follow the documentation at
>>> >> >> >> >>
>>> >> >> >> >>
>>> >> >> >> >>
>>> >> >> >> >>
>>> >> >> >> >> https://gluster.readthedocs.io/en/latest/Administrator%20Guide/Monitoring%20Workload/
>>> >> >> >> >> section: "
>>> >> >> >> >>
>>> >> >> >> >> Running GlusterFS Volume Profile Command"
>>> >> >> >> >>
>>> >> >> >> >> and attach output of "gluster volume profile info",
>>> >> >> >> >>
>>> >> >> >> >> On Fri, Aug 17, 2018 at 11:24 AM Hu Bert
>>> >> >> >> >> <revirii at googlemail.com>
>>> >> >> >> >> wrote:
>>> >> >> >> >>>
>>> >> >> >> >>> Good morning,
>>> >> >> >> >>>
>>> >> >> >> >>> i ran the command during 100% CPU usage and attached the
>>> >> >> >> >>> file.
>>> >> >> >> >>> Hopefully it helps.
>>> >> >> >> >>>
>>> >> >> >> >>> 2018-08-17 7:33 GMT+02:00 Pranith Kumar Karampuri
>>> >> >> >> >>> <pkarampu at redhat.com>:
>>> >> >> >> >>> > Could you do the following on one of the nodes where you
>>> >> >> >> >>> > are
>>> >> >> >> >>> > observing
>>> >> >> >> >>> > high
>>> >> >> >> >>> > CPU usage and attach that file to this thread? We can find
>>> >> >> >> >>> > what
>>> >> >> >> >>> > threads/processes are leading to high usage. Do this for
>>> >> >> >> >>> > say
>>> >> >> >> >>> > 10
>>> >> >> >> >>> > minutes
>>> >> >> >> >>> > when
>>> >> >> >> >>> > you see the ~100% CPU.
>>> >> >> >> >>> >
>>> >> >> >> >>> > top -bHd 5 > /tmp/top.${HOSTNAME}.txt
>>> >> >> >> >>> >
>>> >> >> >> >>> > On Wed, Aug 15, 2018 at 2:37 PM Hu Bert
>>> >> >> >> >>> > <revirii at googlemail.com>
>>> >> >> >> >>> > wrote:
>>> >> >> >> >>> >>
>>> >> >> >> >>> >> Hello again :-)
>>> >> >> >> >>> >>
>>> >> >> >> >>> >> The self heal must have finished as there are no log
>>> >> >> >> >>> >> entries
>>> >> >> >> >>> >> in
>>> >> >> >> >>> >> glustershd.log files anymore. According to munin disk
>>> >> >> >> >>> >> latency
>>> >> >> >> >>> >> (average
>>> >> >> >> >>> >> io wait) has gone down to 100 ms, and disk utilization
>>> >> >> >> >>> >> has
>>> >> >> >> >>> >> gone
>>> >> >> >> >>> >> down
>>> >> >> >> >>> >> to ~60% - both on all servers and hard disks.
>>> >> >> >> >>> >>
>>> >> >> >> >>> >> But now system load on 2 servers (which were in the good
>>> >> >> >> >>> >> state)
>>> >> >> >> >>> >> fluctuates between 60 and 100; the server with the
>>> >> >> >> >>> >> formerly
>>> >> >> >> >>> >> failed
>>> >> >> >> >>> >> disk has a load of 20-30.I've uploaded some munin
>>> >> >> >> >>> >> graphics of
>>> >> >> >> >>> >> the
>>> >> >> >> >>> >> cpu
>>> >> >> >> >>> >> usage:
>>> >> >> >> >>> >>
>>> >> >> >> >>> >> https://abload.de/img/gluster11_cpu31d3a.png
>>> >> >> >> >>> >> https://abload.de/img/gluster12_cpu8sem7.png
>>> >> >> >> >>> >> https://abload.de/img/gluster13_cpud7eni.png
>>> >> >> >> >>> >>
>>> >> >> >> >>> >> This can't be normal. 2 of the servers under heavy load
>>> >> >> >> >>> >> and
>>> >> >> >> >>> >> one
>>> >> >> >> >>> >> not
>>> >> >> >> >>> >> that much. Does anyone have an explanation of this
>>> >> >> >> >>> >> strange
>>> >> >> >> >>> >> behaviour?
>>> >> >> >> >>> >>
>>> >> >> >> >>> >>
>>> >> >> >> >>> >> Thx :-)
>>> >> >> >> >>> >>
>>> >> >> >> >>> >> 2018-08-14 9:37 GMT+02:00 Hu Bert
>>> >> >> >> >>> >> <revirii at googlemail.com>:
>>> >> >> >> >>> >> > Hi there,
>>> >> >> >> >>> >> >
>>> >> >> >> >>> >> > well, it seems the heal has finally finished. Couldn't
>>> >> >> >> >>> >> > see/find
>>> >> >> >> >>> >> > any
>>> >> >> >> >>> >> > related log message; is there such a message in a
>>> >> >> >> >>> >> > specific
>>> >> >> >> >>> >> > log
>>> >> >> >> >>> >> > file?
>>> >> >> >> >>> >> >
>>> >> >> >> >>> >> > But i see the same behaviour when the last heal
>>> >> >> >> >>> >> > finished:
>>> >> >> >> >>> >> > all
>>> >> >> >> >>> >> > CPU
>>> >> >> >> >>> >> > cores are consumed by brick processes; not only by the
>>> >> >> >> >>> >> > formerly
>>> >> >> >> >>> >> > failed
>>> >> >> >> >>> >> > bricksdd1, but by all 4 brick processes (and their
>>> >> >> >> >>> >> > threads).
>>> >> >> >> >>> >> > Load
>>> >> >> >> >>> >> > goes
>>> >> >> >> >>> >> > up to > 100 on the 2 servers with the not-failed brick,
>>> >> >> >> >>> >> > and
>>> >> >> >> >>> >> > glustershd.log gets filled with a lot of entries. Load
>>> >> >> >> >>> >> > on
>>> >> >> >> >>> >> > the
>>> >> >> >> >>> >> > server
>>> >> >> >> >>> >> > with the then failed brick not that high, but still
>>> >> >> >> >>> >> > ~60.
>>> >> >> >> >>> >> >
>>> >> >> >> >>> >> > Is this behaviour normal? Is there some post-heal after
>>> >> >> >> >>> >> > a
>>> >> >> >> >>> >> > heal
>>> >> >> >> >>> >> > has
>>> >> >> >> >>> >> > finished?
>>> >> >> >> >>> >> >
>>> >> >> >> >>> >> > thx in advance :-)
>>> >> >> >> >>> >
>>> >> >> >> >>> >
>>> >> >> >> >>> >
>>> >> >> >> >>> > --
>>> >> >> >> >>> > Pranith
>>> >> >> >> >>
>>> >> >> >> >>
>>> >> >> >> >>
>>> >> >> >> >> --
>>> >> >> >> >> Pranith
>>> >> >> >> >
>>> >> >> >> >
>>> >> >> >> >
>>> >> >> >> > --
>>> >> >> >> > Pranith
>>> >> >> >
>>> >> >> >
>>> >> >> >
>>> >> >> > --
>>> >> >> > Pranith
>>> >> >
>>> >> >
>>> >> >
>>> >> > --
>>> >> > Pranith
>>> >
>>> >
>>> >
>>> > --
>>> > Pranith
>>
>>
>>
>> --
>> Pranith
>
>
>
> --
> Pranith
More information about the Gluster-users
mailing list