A little update.
Hey @juleskers
I finally run perf
sampling cycles for a good 10 minutes and I finally go the results:
Samples: 1M of event 'cycles', Event count (approx.): 354283516692
Children Self Command Shared Object Symbol β
+ 37,12% 0,26% redis-server [kernel.kallsyms] [k] entry_SYSCALL_64_fastpath β
+ 21,22% 0,34% redis-server [kernel.kallsyms] [k] sys_futex β
+ 20,84% 0,39% redis-server [kernel.kallsyms] [k] do_futex β
+ 15,09% 0,00% redis-server libpthread-2.23.so [.] 0xffff801d5934d4bd β
+ 14,69% 0,15% redis-server [kernel.kallsyms] [k] sys_write β
+ 13,93% 0,24% redis-server [kernel.kallsyms] [k] vfs_write β
+ 12,77% 0,07% redis-server [kernel.kallsyms] [k] __vfs_write β
+ 12,65% 0,13% redis-server [kernel.kallsyms] [k] new_sync_write β
+ 11,40% 0,00% redis-server [unknown] [k] 0x0000000000000200 β
+ 10,77% 0,09% redis-server [kernel.kallsyms] [k] sock_write_iter β
+ 10,67% 0,05% redis-server [kernel.kallsyms] [k] sock_sendmsg β
+ 10,55% 0,20% redis-server libpthread-2.23.so [.] __lll_unlock_wake β
+ 10,43% 0,07% redis-server [kernel.kallsyms] [k] inet_sendmsg β
+ 10,17% 0,31% redis-server [kernel.kallsyms] [k] tcp_sendmsg β
+ 9,43% 1,48% redis-server [kernel.kallsyms] [k] try_to_wake_up β
+ 9,38% 0,53% redis-server [kernel.kallsyms] [k] futex_wake β
+ 9,35% 0,05% redis-server [kernel.kallsyms] [k] wake_up_q β
+ 9,34% 0,30% redis-server [kernel.kallsyms] [k] futex_wait β
+ 8,83% 0,06% redis-server [kernel.kallsyms] [k] tcp_push β
+ 8,78% 0,05% redis-server [kernel.kallsyms] [k] __tcp_push_pending_frames β
+ 8,70% 0,20% redis-server [kernel.kallsyms] [k] tcp_write_xmit β
+ 8,34% 0,00% redis-server libredis_sql.so [.] std::sys_common::backtrace::__rust_begin_short_backtrace::h668c06fb2cddbaa9 β
+ 8,34% 0,00% redis-server libredis_sql.so [.] std::panicking::try::do_call::h720cfbcbaefe40ad β
+ 8,34% 0,00% redis-server libredis_sql.so [.] __rust_maybe_catch_panic β
+ 8,34% 0,00% redis-server libredis_sql.so [.] _$LT$F$u20$as$u20$alloc..boxed..FnBox$LT$A$GT$$GT$::call_box::h68dc0072d51b9610 β
+ 8,34% 0,00% redis-server libredis_sql.so [.] std::sys::imp::thread::Thread::new::thread_start::hbaf1b5aa1ca8e3ea β
+ 8,34% 0,00% redis-server libpthread-2.23.so [.] start_thread β
+ 8,10% 0,18% redis-server [kernel.kallsyms] [k] futex_wait_queue_me β
+ 7,98% 0,25% redis-server [kernel.kallsyms] [k] tcp_transmit_skb β
+ 7,95% 0,12% redis-server [kernel.kallsyms] [k] schedule β
+ 7,93% 0,00% redis-server [unknown] [k] 0000000000000000 β
+ 7,70% 0,38% redis-server [kernel.kallsyms] [k] __schedule β
+ 7,32% 0,12% redis-server [kernel.kallsyms] [k] ip_queue_xmit β
+ 7,17% 0,32% redis-server libpthread-2.23.so [.] __lll_lock_wait β
+ 7,15% 0,03% redis-server [kernel.kallsyms] [k] ip_local_out β
+ 6,44% 0,00% redis-server [unknown] [k] 0x0000000001010401 β
+ 5,82% 1,25% redis-server libredis_sql.so [.] redis_sql::redis::listen_and_execute::h1ab708507bc22d52 β
+ 5,32% 5,24% redis-server [vdso] [.] __vdso_gettimeofday β
Main problem is that I have basically no idea of what this means.
It seems like it using most of the time doing sys_call and most of those system calls are futex related (futex should stand for "Fast Userland muTEX"
Also it seems like most of the time is spend outside the rust module, so I don't believe that the channel implementation is of any concerns, thanks anyway to @Ophirr33 for point out crossbeam.
I also sampled the context switch (that I believe is the count of "Where is the stack pointer when happens the Context Switch event?") with expected results:
Samples: 254K of event 'cs', Event count (approx.): 3428106
Children Self Command Shared Object Symbol β
+ 99,97% 99,97% redis-server [kernel.kallsyms] [k] schedule β
+ 99,09% 0,00% redis-server [kernel.kallsyms] [k] entry_SYSCALL_64_fastpath β
+ 99,05% 0,00% redis-server [kernel.kallsyms] [k] futex_wait_queue_me β
+ 99,05% 0,00% redis-server [kernel.kallsyms] [k] futex_wait β
+ 99,05% 0,00% redis-server [kernel.kallsyms] [k] do_futex β
+ 99,05% 0,00% redis-server [kernel.kallsyms] [k] sys_futex β
+ 67,36% 0,00% redis-server libpthread-2.23.so [.] __lll_lock_wait β
+ 31,71% 0,00% redis-server libpthread-2.23.so [.] pthread_cond_wait@@GLIBC_2.3.2 β
+ 18,33% 0,00% redis-server [unknown] [k] 0x0000000000000200 β
+ 11,77% 0,00% redis-server libredis_sql.so [.] std::collections::hash::map::RandomState::new::KEYS::__init::h2413584b0b846c97 β
+ 11,77% 0,00% redis-server libredis_sql.so [.] _$LT$alloc..vec..Vec$LT$T$GT$$GT$::extend_from_slice::hfa47afa150e7d64a β
+ 11,77% 0,00% redis-server libredis_sql.so [.] _$LT$core..fmt..Write..write_fmt..Adapter$LT$$u27$a$C$$u20$T$GT$$u20$as$u20$core..fmt..Wrβ
+ 11,77% 0,00% redis-server libredis_sql.so [.] _$LT$F$u20$as$u20$alloc..boxed..FnBox$LT$A$GT$$GT$::call_box::h70a0fbbf4fe5a4fe β
+ 11,77% 0,00% redis-server libredis_sql.so [.] std::panicking::default_hook::hf425c768c5ffbbad β
+ 11,77% 0,00% redis-server libpthread-2.23.so [.] start_thread β
+ 10,06% 0,00% redis-server [unknown] [k] 0x0000000001010401 β
+ 9,40% 0,00% redis-server [unknown] [k] 0000000000000000 β
+ 5,56% 0,00% redis-server libredis_sql.so [.] redis_sql::redis::listen_and_execute::h1ab708507bc22d52 β
+ 4,32% 0,00% redis-server [unknown] [k] 0xffffffff000003f8 β
+ 2,07% 0,00% redis-server [unknown] [k] 0x0000001300010080
That again happens inside the futex.
So it seems like there are a lot of locks happenings around that may bound the performance of the application.
Any thoughts? How do I understand where are those locks?