Performance of nightly build on dev got a lot slower
dev is currently running 10.2.0+rnightly.67861.b1fe7903-0, and we are noticing much more load and slow performance:
https://docs.gitlab.com/ce/administration/troubleshooting/debug.html has documentation on techniques to examine why the system is slow.
Using perf top for the unicorn workers, we see this profile:
A long-running unicorn worker had these following threads in gdb:
Thread 6 (Thread 0x7efc8cdf9700 (LWP 6565)):
#0 0x00007efc8da795e7 in __GI_epoll_pwait (epfd=24, events=0x7efc8cdf8590, maxevents=100, timeout=-1, set=0x7efc6161b170) at ../sysdeps/unix/sysv/linux/epoll_pwait.c:42
#1 0x00007efc6f136bd1 in ?? () from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.6.6-x86_64-linux/src/ruby/lib/grpc/2.3/grpc_c.so
#2 0x00007efc6f02f05f in ?? () from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.6.6-x86_64-linux/src/ruby/lib/grpc/2.3/grpc_c.so
#3 0x00007efc6f02f5db in grpc_completion_queue_next () from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.6.6-x86_64-linux/src/ruby/lib/grpc/2.3/grpc_c.so
#4 0x00007efc6f015ba4 in ?? () from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.6.6-x86_64-linux/src/ruby/lib/grpc/2.3/grpc_c.so
#5 0x00007efc8df3ad2e in call_without_gvl (fail_if_interrupted=0, data2=<optimized out>, ubf=<optimized out>, data1=0x0, func=0x7efc6f015aeb) at thread.c:1301
#6 rb_thread_call_without_gvl (func=0x7efc6f015aeb, data1=0x0, ubf=<optimized out>, data2=<optimized out>) at thread.c:1411
#7 0x00007efc6f014e03 in ?? () from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.6.6-x86_64-linux/src/ruby/lib/grpc/2.3/grpc_c.so
#8 0x00007efc8df37b71 in thread_start_func_2 (th=th@entry=0x7efc68749c00, stack_start=<optimized out>) at thread.c:590
#9 0x00007efc8df38630 in thread_start_func_1 (th_ptr=0x7efc68749c00) at thread_pthread.c:882
#10 0x00007efc8d4536ba in start_thread (arg=0x7efc8cdf9700) at pthread_create.c:333
#11 0x00007efc8da793dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
Thread 5 (Thread 0x7efc8e69f700 (LWP 6563)):
#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007efc6f04d062 in gpr_cv_wait () from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.6.6-x86_64-linux/src/ruby/lib/grpc/2.3/grpc_c.so
#2 0x00007efc6f0143d2 in ?? () from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.6.6-x86_64-linux/src/ruby/lib/grpc/2.3/grpc_c.so
#3 0x00007efc8df3ad2e in call_without_gvl (fail_if_interrupted=0, data2=<optimized out>, ubf=<optimized out>, data1=0x0, func=0x7efc6f014336) at thread.c:1301
#4 rb_thread_call_without_gvl (func=0x7efc6f014336, data1=0x0, ubf=<optimized out>, data2=<optimized out>) at thread.c:1411
#5 0x00007efc6f01440d in ?? () from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.6.6-x86_64-linux/src/ruby/lib/grpc/2.3/grpc_c.so
#6 0x00007efc8df37b71 in thread_start_func_2 (th=th@entry=0x7efc68749800, stack_start=<optimized out>) at thread.c:590
#7 0x00007efc8df38630 in thread_start_func_1 (th_ptr=0x7efc68749800) at thread_pthread.c:882
#8 0x00007efc8d4536ba in start_thread (arg=0x7efc8e69f700) at pthread_create.c:333
#9 0x00007efc8da793dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
Thread 4 (Thread 0x7efc62dfe700 (LWP 6562)):
#0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
#1 0x00007efc6f04d0ba in gpr_cv_wait () from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.6.6-x86_64-linux/src/ruby/lib/grpc/2.3/grpc_c.so
#2 0x00007efc6f024bfb in ?? () from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.6.6-x86_64-linux/src/ruby/lib/grpc/2.3/grpc_c.so
#3 0x00007efc6f04d237 in ?? () from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.6.6-x86_64-linux/src/ruby/lib/grpc/2.3/grpc_c.so
#4 0x00007efc8d4536ba in start_thread (arg=0x7efc62dfe700) at pthread_create.c:333
#5 0x00007efc8da793dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
Thread 3 (Thread 0x7efc637ff700 (LWP 6561)):
#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007efc6f04d062 in gpr_cv_wait () from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.6.6-x86_64-linux/src/ruby/lib/grpc/2.3/grpc_c.so
#2 0x00007efc6f01fdb1 in ?? () from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.6.6-x86_64-linux/src/ruby/lib/grpc/2.3/grpc_c.so
#3 0x00007efc6f04d237 in ?? () from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/grpc-1.6.6-x86_64-linux/src/ruby/lib/grpc/2.3/grpc_c.so
#4 0x00007efc8d4536ba in start_thread (arg=0x7efc637ff700) at pthread_create.c:333
#5 0x00007efc8da793dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
---Type <return> to continue, or q <return> to quit---
Thread 2 (Thread 0x7efc8e6ae700 (LWP 6290)):
#0 0x00007efc8da6d70d in poll () at ../sysdeps/unix/syscall-template.S:84
#1 0x00007efc8df3330a in timer_thread_sleep (gvl=0x7efc8c820008) at thread_pthread.c:1455
#2 thread_timer (p=0x7efc8c820008) at thread_pthread.c:1563
#3 0x00007efc8d4536ba in start_thread (arg=0x7efc8e6ae700) at pthread_create.c:333
#4 0x00007efc8da793dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
Thread 1 (Thread 0x7efc8e6a0780 (LWP 6288)):
#0 0x00007efc8e233a19 in realloc () from /opt/gitlab/embedded/lib/libjemalloc.so
#1 0x00007efc8dde2b7c in objspace_xrealloc (objspace=0x7efc8c816000, ptr=0x7efc67f050e0, new_size=129, new_size@entry=32636, old_size=<optimized out>) at gc.c:7698
#2 0x00007efc8dde2e7b in ruby_sized_xrealloc2 (old_n=0, size=1, n=32636, ptr=<optimized out>) at gc.c:7793
#3 ruby_xrealloc2 (ptr=<optimized out>, n=n@entry=129, size=size@entry=1) at gc.c:7799
#4 0x00007efc8deafa2b in str_buf_cat (str=139622798602040, ptr=0x7fff4334910f "t\\-", len=1) at string.c:2488
#5 0x00007efc8de656aa in unescape_nonascii (err=0x7fff433491c0 "", has_property=<synthetic pointer>, encp=0x7fff43349190, buf=139622798602040, enc=0x7efc8c81b000, end=0x7efc6898c096 "",
p=0x7efc6898bc80 "ouch\\-icon\\-precomposed\\.png|apple\\-touch\\-icon\\.png|assets|autocomplete|ci|dashboard|deploy\\.html|explore|favicon\\.ico|files|groups|health_check|help|import|invites|jwt|koding|notification_settings|o"...) at re.c:2380
#6 rb_reg_preprocess (
p=p@entry=0x7efc6898bc00 "\\A/((?-mix:(?-mix:(?!((?i-mx:\\-|\\.well\\-known|404\\.html|422\\.html|500\\.html|502\\.html|503\\.html|abuse_reports|admin|api|apple\\-touch\\-icon\\-precomposed\\.png|apple\\-touch\\-icon\\.png|assets|autocomplete"..., end=0x7efc6898c096 "", enc=enc@entry=0x7efc8c81b000, fixed_enc=fixed_enc@entry=0x7fff43349190, err=err@entry=0x7fff433491c0 "")
at re.c:2404
#7 0x00007efc8de672c0 in rb_reg_prepare_re (re=re@entry=139622879073480, str=str@entry=139622799206040) at re.c:1401
#8 0x00007efc8de67d3b in rb_reg_search0 (set_backref_str=1, reverse=<optimized out>, pos=0, str=139622799206040, re=139622879073480) at re.c:1469
#9 rb_reg_search (re=re@entry=139622879073480, str=str@entry=139622799206040, pos=pos@entry=0, reverse=reverse@entry=0) at re.c:1546
#10 0x00007efc8de683ef in reg_match_pos (pos=0, strp=0x7fff43349360, re=139622879073480) at re.c:2811
#11 rb_reg_match_m (argc=<optimized out>, argv=<optimized out>, re=139622879073480) at re.c:2986
#12 0x00007efc8df12fc0 in vm_call_cfunc_with_frame (ci=<optimized out>, cc=<optimized out>, calling=<optimized out>, reg_cfp=0x7efc8c92ba40, th=0x7efc8c81c000) at vm_insnhelper.c:1642
#13 vm_call_cfunc (th=0x7efc8c81c000, reg_cfp=0x7efc8c92ba40, calling=<optimized out>, ci=<optimized out>, cc=<optimized out>) at vm_insnhelper.c:1737
#14 0x00007efc8df1c609 in vm_exec_core (th=th@entry=0x7efc8c81c000, initial=initial@entry=0) at insns.def:994
#15 0x00007efc8df211d6 in vm_exec (th=th@entry=0x7efc8c81c000) at vm.c:1693
#16 0x00007efc8df21edd in invoke_block (block=0x7efc8c92bba0, opt_pc=<optimized out>, type=<optimized out>, cref=0x0, self=139622736181880, iseq=0x7efc888b9fa8, th=0x7efc8c81c000) at vm.c:921
#17 invoke_block_from_c_0 (th=0x7efc8c81c000, block=0x7efc8c92bba0, self=139622736181880, argc=<optimized out>, argv=<optimized out>, blockptr=<optimized out>, cref=0x0, splattable=1)
at vm.c:971
#18 0x00007efc8df2214c in invoke_block_from_c_splattable (cref=0x0, blockptr=0x0, argv=0x7fff43349aa8, argc=1, self=<optimized out>, block=<optimized out>, th=<optimized out>) at vm.c:988
#19 vm_yield (argc=1, argv=0x7fff43349aa8, th=<optimized out>) at vm.c:1023
#20 rb_yield_0 (argv=0x7fff43349aa8, argc=1) at vm_eval.c:1013
#21 rb_yield_1 (val=139622832473160) at vm_eval.c:1019
#22 rb_yield (val=val@entry=139622832473160) at vm_eval.c:1029
#23 0x00007efc8ddb277e in find_all_i (i=139622832473160, ary=139622799198280, argc=<optimized out>, argv=<optimized out>, blockarg=<optimized out>) at enum.c:328
#24 0x00007efc8df17ad4 in vm_yield_with_cfunc (th=th@entry=0x7efc8c81c000, block=block@entry=0x7efc8c92bb60, self=self@entry=139623068826880, argc=1, argv=0x7fff43349bd8,
blockargptr=<optimized out>) at vm_insnhelper.c:2338
#25 0x00007efc8df21e0c in invoke_block_from_c_0 (th=0x7efc8c81c000, block=0x7efc8c92bb60, self=139623068826880, argc=<optimized out>, argv=<optimized out>, blockptr=<optimized out>, cref=0x0,
splattable=1) at vm.c:979
#26 0x00007efc8df2214c in invoke_block_from_c_splattable (cref=0x0, blockptr=0x0, argv=0x7fff43349bd8, argc=1, self=<optimized out>, block=<optimized out>, th=<optimized out>) at vm.c:988
---Type <return> to continue, or q <return> to quit---
#27 vm_yield (argc=1, argv=0x7fff43349bd8, th=<optimized out>) at vm.c:1023
#28 rb_yield_0 (argv=0x7fff43349bd8, argc=1) at vm_eval.c:1013
#29 rb_yield_1 (val=139622832473160) at vm_eval.c:1019
#30 rb_yield (val=<optimized out>) at vm_eval.c:1029
#31 0x00007efc8dd6c6ed in rb_ary_each (ary=139623068826880) at array.c:1815
#32 0x00007efc8df24bd8 in vm_call0_cfunc_with_frame (ci=0x7fff43349c30, cc=0x7fff43349c60, argv=0x0, calling=0x7fff43349c40, th=0x7efc8c81c000) at vm_eval.c:131
#33 vm_call0_cfunc (ci=0x7fff43349c30, argv=0x0, cc=0x7fff43349c60, calling=0x7fff43349c40, th=0x7efc8c81c000) at vm_eval.c:148
#34 vm_call0_body (th=0x7efc8c81c000, calling=calling@entry=0x7fff43349d00, ci=ci@entry=0x7fff43349cf0, cc=cc@entry=0x7fff43349d20, argv=argv@entry=0x0) at vm_eval.c:186
#35 0x00007efc8df251d7 in vm_call0 (me=0x7efc8c9bf908, argv=0x0, argc=0, id=2977, recv=139623068826880, th=<optimized out>) at vm_eval.c:61
#36 rb_call0 (recv=139623068826880, mid=2977, argc=0, argv=0x0, scope=<optimized out>, self=<optimized out>) at vm_eval.c:354
#37 0x00007efc8df1599d in rb_iterate0 (it_proc=it_proc@entry=0x7efc8df26270 <iterate_method>, data1=data1@entry=140734320910080, ifunc=0x7efc775947a8, th=0x7efc8c81c000) at vm_eval.c:1174
#38 0x00007efc8df15b16 in rb_iterate (it_proc=it_proc@entry=0x7efc8df26270 <iterate_method>, data1=data1@entry=140734320910080, bl_proc=bl_proc@entry=0x7efc8ddb2760 <find_all_i>,
data2=data2@entry=139622799198280) at vm_eval.c:1206
#39 0x00007efc8df15b4b in rb_block_call (obj=obj@entry=139623068826880, mid=mid@entry=2977, argc=argc@entry=0, argv=argv@entry=0x0, bl_proc=bl_proc@entry=0x7efc8ddb2760 <find_all_i>,
data2=data2@entry=139622799198280) at vm_eval.c:1237
#40 0x00007efc8ddafec5 in enum_find_all (obj=139623068826880) at enum.c:388
#41 0x00007efc8df12fc0 in vm_call_cfunc_with_frame (ci=<optimized out>, cc=<optimized out>, calling=<optimized out>, reg_cfp=0x7efc8c92bb80, th=0x7efc8c81c000) at vm_insnhelper.c:1642
#42 vm_call_cfunc (th=0x7efc8c81c000, reg_cfp=0x7efc8c92bb80, calling=<optimized out>, ci=<optimized out>, cc=<optimized out>) at vm_insnhelper.c:1737
#43 0x00007efc8df1c538 in vm_exec_core (th=th@entry=0x7efc8c81c000, initial=initial@entry=0) at insns.def:963
#44 0x00007efc8df211d6 in vm_exec (th=th@entry=0x7efc8c81c000) at vm.c:1693
#45 0x00007efc8df24b29 in vm_call0_body (th=0x7efc8c81c000, calling=calling@entry=0x7fff4334a6c0, ci=ci@entry=0x7fff4334a6b0, cc=cc@entry=0x7fff4334a6e0, argv=argv@entry=0x7efc8c82d210)
at vm_eval.c:182
#46 0x00007efc8df251d7 in vm_call0 (me=0x7efc875d12b0, argv=0x7efc8c82d210, argc=1, id=3329, recv=139622742800880, th=<optimized out>) at vm_eval.c:61
#47 rb_call0 (recv=recv@entry=139622742800880, mid=3329, argc=argc@entry=1, argv=argv@entry=0x7efc8c82d210, scope=scope@entry=CALL_PUBLIC, self=self@entry=52) at vm_eval.c:354
#48 0x00007efc8df2545d in send_internal (argc=1, argv=0x7efc8c82d210, recv=139622742800880, scope=CALL_PUBLIC) at vm_eval.c:955
#49 0x00007efc8df12fc0 in vm_call_cfunc_with_frame (ci=<optimized out>, cc=<optimized out>, calling=<optimized out>, reg_cfp=0x7efc8c92c580, th=0x7efc8c81c000) at vm_insnhelper.c:1642
#50 vm_call_cfunc (th=0x7efc8c81c000, reg_cfp=0x7efc8c92c580, calling=<optimized out>, ci=<optimized out>, cc=<optimized out>) at vm_insnhelper.c:1737
#51 0x00007efc8df1c538 in vm_exec_core (th=th@entry=0x7efc8c81c000, initial=initial@entry=0) at insns.def:963
#52 0x00007efc8df211d6 in vm_exec (th=th@entry=0x7efc8c81c000) at vm.c:1693
#53 0x00007efc8df21edd in invoke_block (block=0x7efc8c92c660, opt_pc=<optimized out>, type=<optimized out>, cref=0x0, self=139622872269040, iseq=0x7efc7bb44cd0, th=0x7efc8c81c000) at vm.c:921
#54 invoke_block_from_c_0 (th=0x7efc8c81c000, block=0x7efc8c92c660, self=139622872269040, argc=<optimized out>, argv=<optimized out>, blockptr=<optimized out>, cref=0x0, splattable=1)
at vm.c:971
#55 0x00007efc8df2214c in invoke_block_from_c_splattable (cref=0x0, blockptr=0x0, argv=0x7fff4334aee8, argc=1, self=<optimized out>, block=<optimized out>, th=<optimized out>) at vm.c:988
#56 vm_yield (argc=1, argv=0x7fff4334aee8, th=<optimized out>) at vm.c:1023
#57 rb_yield_0 (argv=0x7fff4334aee8, argc=1) at vm_eval.c:1013
#58 rb_yield_1 (val=139622872120280) at vm_eval.c:1019
#59 rb_yield (val=<optimized out>) at vm_eval.c:1029
#60 0x00007efc8dd6c6ed in rb_ary_each (ary=139622872120240) at array.c:1815
#61 0x00007efc8df12fc0 in vm_call_cfunc_with_frame (ci=<optimized out>, cc=<optimized out>, calling=<optimized out>, reg_cfp=0x7efc8c92c640, th=0x7efc8c81c000) at vm_insnhelper.c:1642
#62 vm_call_cfunc (th=0x7efc8c81c000, reg_cfp=0x7efc8c92c640, calling=<optimized out>, ci=<optimized out>, cc=<optimized out>) at vm_insnhelper.c:1737
#63 0x00007efc8df1c538 in vm_exec_core (th=th@entry=0x7efc8c81c000, initial=initial@entry=0) at insns.def:963
#64 0x00007efc8df211d6 in vm_exec (th=0x7efc8c81c000) at vm.c:1693
#65 0x00007efc8df246e8 in rb_iseq_eval (iseq=<optimized out>) at vm.c:1925
---Type <return> to continue, or q <return> to quit---
#66 0x00007efc8ddc5269 in rb_load_internal0 (th=th@entry=0x7efc8c81c000, fname=139623066174720, wrap=<optimized out>) at load.c:619
#67 0x00007efc8ddc5935 in rb_load_internal (wrap=<optimized out>, fname=<optimized out>) at load.c:649
#68 rb_f_load (argc=<optimized out>, argv=<optimized out>) at load.c:717
#69 0x00007efc8df12fc0 in vm_call_cfunc_with_frame (ci=<optimized out>, cc=<optimized out>, calling=<optimized out>, reg_cfp=0x7efc8c92c880, th=0x7efc8c81c000) at vm_insnhelper.c:1642
#70 vm_call_cfunc (th=0x7efc8c81c000, reg_cfp=0x7efc8c92c880, calling=<optimized out>, ci=<optimized out>, cc=<optimized out>) at vm_insnhelper.c:1737
#71 0x00007efc8df22cee in vm_call_method_each_type (th=th@entry=0x7efc8c81c000, cfp=cfp@entry=0x7efc8c92c880, calling=0x7fff4334b940, ci=<optimized out>, cc=<optimized out>)
at vm_insnhelper.c:2026
#72 0x00007efc8df23263 in vm_call_method (th=0x7efc8c81c000, cfp=0x7efc8c92c880, calling=<optimized out>, ci=<optimized out>, cc=<optimized out>) at vm_insnhelper.c:2176
#73 0x00007efc8df1c609 in vm_exec_core (th=th@entry=0x7efc8c81c000, initial=initial@entry=0) at insns.def:994
#74 0x00007efc8df211d6 in vm_exec (th=0x7efc8c81c000) at vm.c:1693
#75 0x00007efc8df246e8 in rb_iseq_eval (iseq=<optimized out>) at vm.c:1925
#76 0x00007efc8ddc5269 in rb_load_internal0 (th=th@entry=0x7efc8c81c000, fname=139623066249960, wrap=<optimized out>) at load.c:619
#77 0x00007efc8ddc5935 in rb_load_internal (wrap=<optimized out>, fname=<optimized out>) at load.c:649
#78 rb_f_load (argc=<optimized out>, argv=<optimized out>) at load.c:717
#79 0x00007efc8df12fc0 in vm_call_cfunc_with_frame (ci=<optimized out>, cc=<optimized out>, calling=<optimized out>, reg_cfp=0x7efc8c92c900, th=0x7efc8c81c000) at vm_insnhelper.c:1642
#80 vm_call_cfunc (th=0x7efc8c81c000, reg_cfp=0x7efc8c92c900, calling=<optimized out>, ci=<optimized out>, cc=<optimized out>) at vm_insnhelper.c:1737
#81 0x00007efc8df22cee in vm_call_method_each_type (th=th@entry=0x7efc8c81c000, cfp=cfp@entry=0x7efc8c92c900, calling=0x7fff4334c230, ci=<optimized out>, cc=<optimized out>)
at vm_insnhelper.c:2026
#82 0x00007efc8df23263 in vm_call_method (th=0x7efc8c81c000, cfp=0x7efc8c92c900, calling=<optimized out>, ci=<optimized out>, cc=<optimized out>) at vm_insnhelper.c:2176
#83 0x00007efc8df1c609 in vm_exec_core (th=th@entry=0x7efc8c81c000, initial=initial@entry=0) at insns.def:994
#84 0x00007efc8df211d6 in vm_exec (th=0x7efc8c81c000) at vm.c:1693
#85 0x00007efc8df246e8 in rb_iseq_eval (iseq=<optimized out>) at vm.c:1925
#86 0x00007efc8ddc5269 in rb_load_internal0 (th=th@entry=0x7efc8c81c000, fname=139623156012000, wrap=<optimized out>) at load.c:619
#87 0x00007efc8ddc5935 in rb_load_internal (wrap=<optimized out>, fname=<optimized out>) at load.c:649
#88 rb_f_load (argc=<optimized out>, argv=<optimized out>) at load.c:717
#89 0x00007efc8df12fc0 in vm_call_cfunc_with_frame (ci=<optimized out>, cc=<optimized out>, calling=<optimized out>, reg_cfp=0x7efc8c92cc40, th=0x7efc8c81c000) at vm_insnhelper.c:1642
#90 vm_call_cfunc (th=0x7efc8c81c000, reg_cfp=0x7efc8c92cc40, calling=<optimized out>, ci=<optimized out>, cc=<optimized out>) at vm_insnhelper.c:1737
#91 0x00007efc8df22cee in vm_call_method_each_type (th=th@entry=0x7efc8c81c000, cfp=cfp@entry=0x7efc8c92cc40, calling=0x7fff4334cb20, ci=<optimized out>, cc=<optimized out>)
at vm_insnhelper.c:2026
#92 0x00007efc8df23263 in vm_call_method (th=0x7efc8c81c000, cfp=0x7efc8c92cc40, calling=<optimized out>, ci=<optimized out>, cc=<optimized out>) at vm_insnhelper.c:2176
#93 0x00007efc8df1c609 in vm_exec_core (th=th@entry=0x7efc8c81c000, initial=initial@entry=0) at insns.def:994
#94 0x00007efc8df211d6 in vm_exec (th=0x7efc8c81c000) at vm.c:1693
#95 0x00007efc8df2494d in rb_iseq_eval_main (iseq=iseq@entry=0x7efc8c795808) at vm.c:1936
#96 0x00007efc8ddbf5bd in ruby_exec_internal (n=0x7efc8c795808) at eval.c:245
#97 0x00007efc8ddc174d in ruby_exec_node (n=n@entry=0x7efc8c795808) at eval.c:310
#98 0x00007efc8ddc40fe in ruby_run_node (n=0x7efc8c795808) at eval.c:302
#99 0x000000000040086b in main (argc=10, argv=0x7fff4334d308) at main.c:36This is the Ruby backtrace:
from /opt/gitlab/embedded/bin/bundle:23:in `<main>'
from /opt/gitlab/embedded/bin/bundle:23:in `load'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/bundler-1.13.7/exe/bundle:26:in `<top (required)>'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/bundler-1.13.7/lib/bundler/friendly_errors.rb:100:in `with_friendly_errors'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/bundler-1.13.7/exe/bundle:34:in `block in <top (required)>'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/bundler-1.13.7/lib/bundler/cli.rb:11:in `start'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/bundler-1.13.7/lib/bundler/vendor/thor/lib/thor/base.rb:440:in `start'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/bundler-1.13.7/lib/bundler/cli.rb:20:in `dispatch'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/bundler-1.13.7/lib/bundler/vendor/thor/lib/thor.rb:359:in `dispatch'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/bundler-1.13.7/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/bundler-1.13.7/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/bundler-1.13.7/lib/bundler/cli.rb:332:in `exec'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/bundler-1.13.7/lib/bundler/cli/exec.rb:27:in `run'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/bundler-1.13.7/lib/bundler/cli/exec.rb:74:in `kernel_load'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/bundler-1.13.7/lib/bundler/cli/exec.rb:74:in `load'
from /opt/gitlab/embedded/bin/unicorn:23:in `<top (required)>'
from /opt/gitlab/embedded/bin/unicorn:23:in `load'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/unicorn-5.1.0/bin/unicorn:126:in `<top (required)>'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/unicorn-5.1.0/lib/unicorn/http_server.rb:283:in `join'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/unicorn-5.1.0/lib/unicorn/http_server.rb:519:in `maintain_worker_count'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/unicorn-5.1.0/lib/unicorn/http_server.rb:508:in `spawn_missing_workers'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/unicorn-5.1.0/lib/unicorn/http_server.rb:658:in `worker_loop'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/unicorn-worker-killer-0.4.4/lib/unicorn/worker_killer.rb:52:in `process_client'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/unicorn-5.1.0/lib/unicorn/http_server.rb:562:in `process_client'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/rack-1.6.8/lib/rack/urlmap.rb:50:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/rack-1.6.8/lib/rack/urlmap.rb:50:in `each'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/rack-1.6.8/lib/rack/urlmap.rb:66:in `block in call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.8/lib/rails/railtie.rb:194:in `method_missing'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.8/lib/rails/railtie.rb:194:in `public_send'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.8/lib/rails/application.rb:165:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.8/lib/rails/engine.rb:518:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/sentry-raven-2.5.3/lib/raven/integrations/rack.rb:50:in `call'
from /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/metrics/requests_rack_middleware.rb:27:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/rack-1.6.8/lib/rack/sendfile.rb:113:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/rack-1.6.8/lib/rack/lock.rb:17:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/rack-1.6.8/lib/rack/runtime.rb:18:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/rack-1.6.8/lib/rack/methodoverride.rb:22:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/actionpack-4.2.8/lib/action_dispatch/middleware/request_id.rb:21:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/request_store-1.3.1/lib/request_store/middleware.rb:9:in `call'
from /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/request_context.rb:18:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.8/lib/rails/rack/logger.rb:20:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/tagged_logging.rb:68:in `tagged'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/tagged_logging.rb:26:in `tagged'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/tagged_logging.rb:68:in `block in tagged'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.8/lib/rails/rack/logger.rb:20:in `block in call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/railties-4.2.8/lib/rails/rack/logger.rb:38:in `call_app'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/actionpack-4.2.8/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/actionpack-4.2.8/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/actionpack-4.2.8/lib/action_dispatch/middleware/remote_ip.rb:78:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/actionpack-4.2.8/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/callbacks.rb:81:in `run_callbacks'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/callbacks.rb:778:in `_run_call_callbacks'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/callbacks.rb:88:in `__run_callbacks__'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/actionpack-4.2.8/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.8/lib/active_record/connection_adapters/abstract/connection_pool.rb:653:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/activerecord-4.2.8/lib/active_record/query_cache.rb:36:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/actionpack-4.2.8/lib/action_dispatch/middleware/cookies.rb:560:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/rack-1.6.8/lib/rack/session/abstract/id.rb:220:in `call'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/rack-1.6.8/lib/rack/session/abstract/id.rb:225:in `context'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/actionpack-4.2.8/lib/action_dispatch/middleware/flash.rb:260:in `call'
from /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/middleware/read_only.rb:17:in `call'
from /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/middleware/read_only.rb:41:in `disallowed_request?'
from /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/middleware/read_only.rb:69:in `whitelisted_routes'
from /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/middleware/read_only.rb:77:in `grack_route'
from /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/middleware/read_only.rb:65:in `route_hash'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/actionpack-4.2.8/lib/action_dispatch/routing/route_set.rb:832:in `recognize_path'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/actionpack-4.2.8/lib/action_dispatch/journey/router.rb:59:in `recognize'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/actionpack-4.2.8/lib/action_dispatch/journey/router.rb:100:in `find_routes'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/actionpack-4.2.8/lib/action_dispatch/journey/router.rb:100:in `find_all'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/actionpack-4.2.8/lib/action_dispatch/journey/router.rb:100:in `each'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/actionpack-4.2.8/lib/action_dispatch/journey/router.rb:101:in `block in find_routes'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/actionpack-4.2.8/lib/action_dispatch/journey/path/pattern.rb:165:in `match'
from /opt/gitlab/embedded/lib/ruby/gems/2.3.0/gems/actionpack-4.2.8/lib/action_dispatch/journey/path/pattern.rb:165:in `match'The gdb backtrace has the most interesting information. Most of the threads are idle, but thread 1 is doing some heavy memory allocation due to the regular expression parsing of the routes:
Thread 1 (Thread 0x7efc8e6a0780 (LWP 6288)):
#0 0x00007efc8e233a19 in realloc () from /opt/gitlab/embedded/lib/libjemalloc.so
#1 0x00007efc8dde2b7c in objspace_xrealloc (objspace=0x7efc8c816000, ptr=0x7efc67f050e0, new_size=129, new_size@entry=32636, old_size=<optimized out>) at gc.c:7698
#2 0x00007efc8dde2e7b in ruby_sized_xrealloc2 (old_n=0, size=1, n=32636, ptr=<optimized out>) at gc.c:7793
#3 ruby_xrealloc2 (ptr=<optimized out>, n=n@entry=129, size=size@entry=1) at gc.c:7799
#4 0x00007efc8deafa2b in str_buf_cat (str=139622798602040, ptr=0x7fff4334910f "t\\-", len=1) at string.c:2488
#5 0x00007efc8de656aa in unescape_nonascii (err=0x7fff433491c0 "", has_property=<synthetic pointer>, encp=0x7fff43349190, buf=139622798602040, enc=0x7efc8c81b000, end=0x7efc6898c096 "",
p=0x7efc6898bc80 "ouch\\-icon\\-precomposed\\.png|apple\\-touch\\-icon\\.png|assets|autocomplete|ci|dashboard|deploy\\.html|explore|favicon\\.ico|files|groups|health_check|help|import|invites|jwt|koding|notification_settings|o"...) at re.c:2380
#6 rb_reg_preprocess (
p=p@entry=0x7efc6898bc00 "\\A/((?-mix:(?-mix:(?!((?i-mx:\\-|\\.well\\-known|404\\.html|422\\.html|500\\.html|502\\.html|503\\.html|abuse_reports|admin|api|apple\\-touch\\-icon\\-precomposed\\.png|apple\\-touch\\-icon\\.png|assets|autocomplete"..., end=0x7efc6898c096 "", enc=enc@entry=0x7efc8c81b000, fixed_enc=fixed_enc@entry=0x7fff43349190, err=err@entry=0x7fff433491c0 "")
at re.c:2404
#7 0x00007efc8de672c0 in rb_reg_prepare_re (re=re@entry=139622879073480, str=str@entry=139622799206040) at re.c:1401
#8 0x00007efc8de67d3b in rb_reg_search0 (set_backref_str=1, reverse=<optimized out>, pos=0, str=139622799206040, re=139622879073480) at re.c:1469
#9 rb_reg_search (re=re@entry=139622879073480, str=str@entry=139622799206040, pos=pos@entry=0, reverse=reverse@entry=0) at re.c:1546
#10 0x00007efc8de683ef in reg_match_pos (pos=0, strp=0x7fff43349360, re=139622879073480) at re.c:2811
#11 rb_reg_match_m (argc=<optimized out>, argv=<optimized out>, re=139622879073480) at re.c:2986
#12 0x00007efc8df12fc0 in vm_call_cfunc_with_frame (ci=<optimized out>, cc=<optimized out>, calling=<optimized out>, reg_cfp=0x7efc8c92ba40, th=0x7efc8c81c000) at vm_insnhelper.c:1642
#13 vm_call_cfunc (th=0x7efc8c81c000, reg_cfp=0x7efc8c92ba40, calling=<optimized out>, ci=<optimized out>, cc=<optimized out>) at vm_insnhelper.c:1737
#14 0x00007efc8df1c609 in vm_exec_core (th=th@entry=0x7efc8c81c000, initial=initial@entry=0) at insns.def:994
#15 0x00007efc8df211d6 in vm_exec (th=th@entry=0x7efc8c81c000) at vm.c:1693
#16 0x00007efc8df21edd in invoke_block (block=0x7efc8c92bba0, opt_pc=<optimized out>, type=<optimized out>, cref=0x0, self=139622736181880, iseq=0x7efc888b9fa8, th=0x7efc8c81c000) at vm.c:921
#17 invoke_block_from_c_0 (th=0x7efc8c81c000, block=0x7efc8c92bba0, self=139622736181880, argc=<optimized out>, argv=<optimized out>, blockptr=<optimized out>, cref=0x0, splattable=1)
at vm.c:971
#18 0x00007efc8df2214c in invoke_block_from_c_splattable (cref=0x0, blockptr=0x0, argv=0x7fff43349aa8, argc=1, self=<optimized out>, block=<optimized out>, th=<optimized out>) at vm.c:988
#19 vm_yield (argc=1, argv=0x7fff43349aa8, th=<optimized out>) at vm.c:1023
#20 rb_yield_0 (argv=0x7fff43349aa8, argc=1) at vm_eval.c:1013
#21 rb_yield_1 (val=139622832473160) at vm_eval.c:1019
#22 rb_yield (val=val@entry=139622832473160) at vm_eval.c:1029
#23 0x00007efc8ddb277e in find_all_i (i=139622832473160, ary=139622799198280, argc=<optimized out>, argv=<optimized out>, blockarg=<optimized out>) at enum.c:328
#24 0x00007efc8df17ad4 in vm_yield_with_cfunc (th=th@entry=0x7efc8c81c000, block=block@entry=0x7efc8c92bb60, self=self@entry=139623068826880, argc=1, argv=0x7fff43349bd8,
blockargptr=<optimized out>) at vm_insnhelper.c:2338
#25 0x00007efc8df21e0c in invoke_block_from_c_0 (th=0x7efc8c81c000, block=0x7efc8c92bb60, self=139623068826880, argc=<optimized out>, argv=<optimized out>, blockptr=<optimized out>, cref=0x0I've known for a while that our route rules (try running bundle exec rake routes) have become incredibly complicated with long regular expressions, and I'm wondering if this is having an impact now when many more requests are handled.
It could be this is just a side effect of unicorn workers restarting, but at the time of taking these performance dumps I didn't see a correlation between the workers that were restarted and this process that I benchmarked.