search

sozu-proxy / sozu

Sōzu HTTP reverse proxy, configurable at runtime, fast and safe, built in Rust. It is awesome!
https://www.sozu.io/
GNU Affero General Public License v3.0
3k stars 187 forks source link

overhead of time measurements #500

Open Geal opened 6 years ago

Geal commented 6 years ago

In a stress test, I got the following profiling info:

  Children      Self  Command  Shared Object       Symbol                                                                                                                                                                                                                         
-   80.05%     0.28%  sozu     [kernel.kallsyms]   [k] entry_SYSCALL_64_fastpath                                                                                                                                                                                                  
   - 79.77% entry_SYSCALL_64_fastpath                                                                                                                                                                                                                                             
      - 59.34% sys_clock_gettime                                                                                                                                                                                                                                                  
         - 31.99% posix_ktime_get_ts                                                                                                                                                                                                                                              
            - 31.96% ktime_get_ts64                                                                                                                                                                                                                                               
               - 31.88% timekeeping_get_ns                                                                                                                                                                                                                                        
                  - 31.81% tk_clock_read                                                                                                                                                                                                                                          
                       read_hpet                                                                                                                                                                                                                                                  
         - 26.92% posix_clock_realtime_get                                                                                                                                                                                                                                        
            - 26.91% getnstimeofday64                                                                                                                                                                                                                                             
               - 26.91% __getnstimeofday64                                                                                                                                                                                                                                        
                  - 26.86% timekeeping_get_ns                                                                                                                                                                                                                                     
                     - 26.83% tk_clock_read                                                                                                                                                                                                                                       
                          read_hpet                                                                                                                                                                                                                                               
      - 16.41% sys_sendto                                                                                                                                                                                                                                                         
         - 16.36% SYSC_sendto                                                                                                                                                                                                                                                     
            - 15.77% sock_sendmsg                                                                                                                                                                                                                                                 
               - 15.53% inet_sendmsg                                                                                                                                                                                                                                              
                  + 9.72% udp_sendmsg                                                                                                                                                                                                                                             
                  + 5.73% tcp_sendmsg                                                                                                                                                                                                                                             
      - 2.08% sys_recvfrom                                                                                                                                                                                                                                                        
         - 2.06% SYSC_recvfrom                                                                                                                                                                                                                                                    
            - 1.84% sock_recvmsg                                                                                                                                                                                                                                                  
               - 1.74% sock_recvmsg_nosec                                                                                                                                                                                                                                         
                  - 1.72% inet_recvmsg                                                                                                                                                                                                                                            
                     - 1.68% tcp_recvmsg  
                        + 0.97% tcp_cleanup_rbuf

the calls to sys_clock_gettime corresponds to request for the monotonic time, to measure timeouts, service time, response time, etc. I was not really expecting this to be a performance issue, so it might be useful to investigate.

I saw this in dmesg:

[321231.649153] kworker/dying (10182) used greatest stack depth: 12360 bytes left
[335323.734091] clocksource: timekeeping watchdog on CPU5: Marking clocksource 'tsc' as unstable because the skew is too large:
[335323.737925] clocksource:                       'hpet' wd_now: 5ca548fd wd_last: 5932c25f mask: ffffffff
[335323.808006] clocksource:                       'tsc' cs_now: bb8a0f7168a0d4 cs_last: bb8a0f234df0c3 mask: ffffffffffffffff
[335323.808733] tsc: Marking TSC unstable due to clocksource watchdog
[335323.809573] TSC found unstable after boot, most likely due to broken BIOS. Use 'tsc=unstable'.
[335323.812815] sched_clock: Marking unstable (335323789992910, 19578389)<-(335324017026353, -207454544)
[335323.813890] clocksource: Switched to clocksource hpet
[335538.326632] hrtimer: interrupt took 6663395 ns

So is the tsc based clock source really unreliable?

Geal commented 3 years ago

not much we can do from sozu's code, if the kernel suddenly decides to use the HPET clock, everything will get slow. Maybe having a configuration check somewhere at startup?

56quarters commented 3 years ago

Maybe having a configuration check somewhere at startup?

Good idea. Could also be part of some kind of a "generate troubleshooting information" tool / command.