Re: PROBLEM: spurious temporary freeze, scheduler and preempt problem ?

[Eric]

On Wednesday 18 February 2004 9:26 am, Brice Figureau wrote:
Someone correct me if I'm way off base, but have you tried
	scheduler=deadline
To try the different kernel schedulers?
Im not sure about the keyword, but do a quick google or search lkml and you'll 
see the correct keyword and the different schedulers you can try.


> Hi all,
>
> I'm working on a java server that uses some native libs (aka JNI). The
> server is poll(2)ing a TCP socket with the help of NIO, and dispatch
> network requests to a pool of a threads (currently 4) that send back
> responses to the client. Those threads are mostly executing native code
> (with JNI). The server is using a mysql engine running on the same host
> to store a few things (about 10 records stored per seconds if that
> matters).
>
> I'm running 2.6.3-rc2 on a UP Celeron (same problem on a PIII too)
> system with plenty of RAM, but which runs several other daemons
> (postfix, djbdns... those daemons were not loading the machine during
> the tests).
> The machine was never swapping (see the vmstat output below [2,3]).
>
> I noticed a few weeks ago that when I try to stress-test this particular
> application the host on which it runs completely freeze for 3 to 5
> seconds, nothing seems to run at all during this time (this was
> especially visible during my first test as it was my devl computer
> running X and the whole screen was frozen).
>
> I decided to perform torough testing running on quiet machine without X.
> During my testbed I tried to capture most data I could (vmstat,
> profiling...).
>
> What I've seen is the following:
>
> 1) During the freeze, the system was using almost 80% CPU time in kernel
> and the remaining in user space
>
> 2) During the freeze, even changing from virtual-console to another
> could have been frozen. No virtual-console would be alive.
>
> 3) a top d 1 or top d 0.5 show that my application was running before
> the freeze and after the freeze, with 80% of CPU time in kernel space.
>
> 4) load was increasing faster than I could think (>19 after 30 seconds)
>
> I first thought that a profiling (with profile=1 or oprofile) would give
> me a good candidate about the problem, but I'm not sure right now (see
> the profile output at the end of the mail [4,5])
>
> After that I tried to run vmstat 1 to have a better idea of the problem
> [2,3]. You can see the high amount of context-switch and interrupt. I
> think that this is because vmstat was stuck (like the other process)
> during a few seconds, but the kernel counters were still incrementing.
>
> Then I finally tried several differents kernel and found the following
> results:
>
> 2.6.3-rc2  -> exhibit the high load problem
> 2.4.25-rc3 -> immune to the problem, the load never goes beyong 1.20
>
> I finally did a binary search between several version of 2.6 and found
> that any kernel *before* 2.6.0-test5 (included) are immune to the
> problem and any kernel *after* 2.6.0-test6 (included) have the same load
> problem.
>
> On a side note, 2.6.0-test4-mm2 (the only mm kernel I had already
> compiled) had the problem too.
>
> So what are the differences between test5 and test6 ?
> It seems that the sched_interactive patch from Con Kolivas was included
> in test6, can it be the cause ?
>
> By running and looking at a 'top d 0.5' I couldn't spot any bizarre
> dynamic priorities (my java app is at 15 or 16, never more).
> The only difference I could spot is that kernel with interactive
> scheduler seemed to make runnable several java threads at the same time
> (about 3 to 4) unlike the previous scheduler (only 1~2 runnable process
> at any time).
>
> Something I should also say is that I tested a 2.6.3-rc2 *without*
> preempt and found this kernel to be immune, too.
>
> I also removed all the sql code in my application and no more freeze !
> (Although that does not explain why the combination of the two gives
> those results).
>
> Can someone help me find what the problem is ?
>
> Useful data:
>
> 1) ver_linux
> Linux arsenic 2.6.3-rc2 #2 SMP Wed Feb 18 11:35:24 CET 2004 i686 unknown
> unknown GNU/Linux
>
> Gnu C                  3.3.1
> Gnu make               3.80
> util-linux             2.12
> mount                  2.11z
> module-init-tools      0.9.11a
> e2fsprogs              1.34
> quota-tools            3.09.
> PPP                    2.4.1
> nfs-utils              1.0.5
> Linux C Library        2.3.2
> Dynamic linker (ldd)   2.3.2
> Procps                 3.1.11
> Net-tools              1.60
> Console-tools          0.2.3
> Sh-utils               5.0
> Modules Loaded
>
>
> 2) vmstat for a kernel with the problem:
>
> procs -----------memory---------- ---swap-- -----io---- --system--
> ----cpu---- r  b   swpd   free   buff  cache   si   so    bi    bo   in   
> cs us sy id wa 3  0      0 371136   8044  61096    0    0    16   120 1035 
>  351 63  3 30  4 3  0      0 371136   8044  61112    0    0    12     0
> 1033   532 78  4 18  0 21  0      0 371024   8064  61116    0    0     0  
> 148 9038 630633 29 71  0  0 4  0      0 371024   8064  61120    0    0    
> 0     0 1064 43014 58 42  0  0 4  0      0 371024   8064  61120    0    0  
>   0     0 1159 78750 38 62  0  0 4  0      0 371040   8080  61120    0    0
>     0    76 4298 309703 29 71  0  0 15  0      0 370976   8096  61120    0 
>   0     0    96 6833 501193 27 73  0  0 3  0      0 370992   8096  61124   
> 0    0     0     0 1094 44694 56 44  0  0 3  0      0 370992   8096  61124 
>   0    0     0     0 1087 65851 42 58  0  0 16  0      0 371024   8112 
> 61124    0    0     0    76 10511 794459 26 74  0  0 4  0      0 371024  
> 8112  61124    0    0     0     0 1035 56591 50 50  0  0 3  0      0 371024
>   8112  61124    0    0     0     0 1025 63930 41 59  0  0 3  0      0
> 371024   8112  61124    0    0     0     0 1007 54424 47 53  0  0 5  0     
> 0 371024   8112  61124    0    0     0     0 1100 56909 53 47  0  0 5  0   
>   0 370960   8128  61128    0    0     0    60 1154 71518 37 63  0  0 4  0 
>     0 370960   8128  61128    0    0     0     0 1041 54728 51 49  0  0 12 
> 0      0 370960   8128  61128    0    0     0    12 3147 223442 31 69  0  0
>
> huge freeze before the following line
> 15  0      0 370952   8152  61128    0    0     0   112 13393 1014908 25 75
>  0  0 3  0      0 370944   8152  61128    0    0     0     0 1006 55046 43
> 57  0  0 3  0      0 370944   8152  61128    0    0     0     0 1111 66487
> 40 60  0  0 21  0      0 370920   8168  61128    0    0     0    68 20308
> 1531575 26 74  0  0 procs -----------memory---------- ---swap-- -----io----
> --system-- ----cpu---- r  b   swpd   free   buff  cache   si   so    bi   
> bo   in    cs us sy id wa 14  0      0 370888   8176  61132    0    0     0
>    20 4228 313614 25 75  0  0 18  0      0 370912   8200  61132    0    0  
>   0   112 8133 610932 26 74  0  0 8  0      0 371488   8200  61132    0   
> 0     0    48 1513 104797 31 69  0  0 29  0      0 371440   8216  61132   
> 0    0     0    68 4490 333022 26 74  0  0
>
> 3) vmstat for a kernel without the problem
>
> procs -----------memory---------- ---swap-- -----io---- --system--
> ----cpu---- r  b   swpd   free   buff  cache   si   so    bi    bo   in   
> cs us sy id wa 0  0      0 389060   7884  57472    0    0   153    38 1023 
>   91  5  3 85  7 2  0      0 388020   7884  57492    0    0     4     0
> 1012   127  3  3 92  2 2  0      0 380940   7884  57492    0    0     0    
> 0 1010   440 94  6  0  0 0  1      0 378636   7928  58460    0    0  1004  
>  16 1173   330 47  5 21 26 0  0      0 378276   7928  58600    0    0   136
>     0 1038   291 68 10 11 11 3  0      0 377828   7944  58652    0    0   
> 52   268 1021   261 68 10 17  5 3  0      0 377188   7952  58768    0    0 
>  112    24 1017   278 63  7 24  6 2  0      0 377060   7952  58828    0   
> 0    56     0 1016   276 57  7 27  9 3  0      0 377060   7960  58864    0 
>   0    36    88 1020   223 65  8 23  4 0  0      0 376868   7960  58896   
> 0    0    28     0 1009   234 66 10 23  1 3  0      0 376820   7968  58936 
>   0    0    36   104 1032   229 61  9 26  4 3  0      0 376756   7968 
> 58972    0    0    32     0 1010   274 47  6 43  3 0  0      0 376564  
> 7968  59000    0    0    28     0 1009   415 66  3 30  1 5  0      0 376308
>   7976  59012    0    0     8    92 1016   387 56  5 39  0 2  0      0
> 376236   7976  59080    0    0    68     0 1004   290 78  1 21  0 4  0     
> 0 375980   7984  59088    0    0     4   204 1056   408 45  5 50  0 1  0   
>   0 375788   7984  59092    0    0     4     0 1003   330 87  4  9  0 0  0 
>     0 375596   7984  59096    0    0     0     0 1002   281 74  3 23  0 0 
> 0      0 375404   7992  59108    0    0     8   120 1024   289 43  4 39 15
> 1  0      0 375276   7992  59124    0    0    12     0 1005   394 39  3 57 
> 1 4  0      0 375204   8000  59132    0    0     4    16 1006  1083 95  5 
> 0  0 procs -----------memory---------- ---swap-- -----io---- --system--
> ----cpu---- r  b   swpd   free   buff  cache   si   so    bi    bo   in   
> cs us sy id wa 3  0      0 375140   8000  59132    0    0     0     0 1002
> 95433 37 63  0  0 3  0      0 375060   8000  59136    0    0     0     0
> 1012 102262 33 67  0  0 6  0      0 375044   8008  59136    0    0     0  
> 112 1025 83959 43 57  0  0 5  0      0 374988   8008  59136    0    0     0
>     0 1002   232 98  2  0  0 3  0      0 375052   8016  59136    0    0    
> 0    20 1005   211 98  2  0  0 3  0      0 375052   8016  59136    0    0  
>   0     0 1007 43272 71 29  0  0 2  0      0 375052   8016  59140    0    0
>     0     0 1023 82448 59 41  0  0 3  0      0 374988   8024  59140    0   
> 0     0    84 1022 132541 39 61  0  0 3  0      0 374988   8024  59140    0
>    0     0     0 1002 21207 89 11  0  0 5  0      0 375004   8032  59144   
> 0    0     0    20 1005 45680 75 25  0  0 3  0      0 375004   8032  59144 
>   0    0     0     0 1012 24392 82 18  0  0 3  0      0 375004   8032 
> 59144    0    0     0     0 1015 82373 48 52  0  0 2  0      0 375004  
> 8032  59144    0    0     0     0 1005 77767 61 39  0  0 4  0      0 375020
>   8040  59144    0    0     0    68 1009 148047 31 69  0  0 3  0      0
> 375020   8048  59144    0    0     0    32 1008 127918 38 62  0  0 1  0    
>  0 374956   8048  59144    0    0     0     0 1011 91847 39 61  0  0 3  0  
>    0 374956   8048  59148    0    0     0     0 1002 94842 51 49  0  0 4  0
>      0 374972   8048  59148    0    0     0     0 1006 126960 38 62  0  0 2
>  0      0 374972   8056  59148    0    0     0    60 1009 76808 65 35  0  0
> 1  0      0 374972   8064  59148    0    0     0   184 1037 111781 32 68  0
>  0 2  0      0 374972   8064  59148    0    0     0     0 1002 120766 36 64
>  0  0
>
> 4) readprofile for a kernel with the problem (analysis during atmost 1min)
>
> c0191b55 proc_pid_stat                                14   0.0108
> c01936cc write_profile                                15   0.0794
> c0241e40 do_con_write                                 15   0.0081
> c0130e95 sys_tgkill                                   16   0.0438
> c0176dd2 __d_lookup                                   18   0.0496
> c018cf88 task_statm                                   18   0.1818
> c02037d2 __copy_user_intel                            20   0.1163
> c02025f3 number                                       28   0.0452
> c014e3a8 do_anonymous_page                            32   0.0516
> c012eab4 kill_something_info                         175   0.5591
> c0109480 syscall_call                                239  21.7273
> c01354ad find_task_by_pid                            280   3.6364
> c012dd86 check_kill_permission                       316   1.8588
> c010948b syscall_exit                                336  30.5455
> c0109f34 device_not_available                        360   8.5714
> c0111313 restore_i387_fxsave                         403   2.4132
> c01209af __might_sleep                               625   3.0340
> c01113ba restore_i387                                673   4.6414
> c010870a restore_sigcontext                          753   2.4770
> c0130e43 sys_kill                                    757   9.2317
> c0108a73 setup_sigcontext                            935   3.1481
> c0114ffa sched_clock                                1189   9.0076
> c0111111 save_i387_fxsave                           1214   4.8367
> c011120c save_i387                                  1872   7.1179
> c0111027 convert_fxsr_from_user                     1974   8.4359
> c012ea44 kill_proc_info                             2217  19.7946
> c0130613 sys_rt_sigprocmask                         2220   5.2857
> c0108b9c setup_frame                                2250   4.8077
> c010883a sys_sigreturn                              3405  13.3008
> c0110eca convert_fxsr_to_user                       3620  10.3725
> c0109009 handle_signal                              3927  11.6183
> c01084cc sys_rt_sigsuspend                          4121  13.4235
> c020399a __copy_from_user_ll                        6233  54.6754
> c010915b do_signal                                  6656  24.7435
> c020392a __copy_to_user_ll                          7219  64.4554
> c01300d4 get_signal_to_deliver                      9293   8.6447
> c012e484 group_send_sig_info                       14040  13.2578
> c011e5a1 schedule                                  15029   8.2396
> c0109454 system_call                               21609 491.1136
> 00000000 total                                    114435   0.0412
>
> 5) profile for a kernel without the problem (in fact a 2.6.3-rc2 without
> preempt)
>
> c027983c vgacon_cursor                                24   0.0612
> c0108d64 syscall_call                                 25   2.2727
> c013a306 do_anonymous_page                            25   0.0627
> c016e47c pid_revalidate                               26   0.1486
> c01d7a86 __copy_user_intel                            28   0.1628
> c010f2ed restore_i387_fxsave                          31   0.2138
> c0127742 find_task_by_pid                             31   0.4026
> c020d598 conv_uni_to_pc                               34   0.1932
> c02c2b7f tcp_poll                                     36   0.0945
> c010f17d save_i387_fxsave                             40   0.2062
> c0153114 link_path_walk                               43   0.0205
> c016edac get_tgid_list                                47   0.3072
> c0147da7 fget_light                                   49   0.4949
> c015c21f __d_lookup                                   51   0.2099
> c021308d do_con_write                                 53   0.0287
> c0123e02 sys_kill                                     57   0.6951
> c010842a setup_sigcontext                             59   0.1987
> c01d6bba vsnprintf                                    63   0.0510
> c0108144 restore_sigcontext                           66   0.2171
> c01702da proc_pid_stat                                69   0.0681
> c0116bed __might_sleep                                70   0.4516
> c0108553 setup_frame                                  72   0.1538
> c016c9de task_statm                                   83   0.8384
> c0112a5e sched_clock                                  90   0.6818
> c0108274 sys_sigreturn                                93   0.4794
> c01236d1 sys_rt_sigprocmask                           99   0.2750
> c01089c0 handle_signal                               122   0.4342
> c010f093 convert_fxsr_from_user                      143   0.6111
> c0107f42 sys_rt_sigsuspend                           146   0.5911
> c01d694f number                                      157   0.2536
> c010ef36 convert_fxsr_to_user                        179   0.5129
> c0108ad9 do_signal                                   463   1.8016
> c01d7c4e __copy_from_user_ll                         476   4.1754
> c0123300 get_signal_to_deliver                       522   0.6788
> c0121d45 group_send_sig_info                         646   0.7242
> c01d7bde __copy_to_user_ll                           695   6.2054
> c011577c schedule                                    889   0.6679
> c0108d38 system_call                                1642  37.3182
> c0106d59 default_idle                              53370 1241.1628
> 00000000 total                                     61980   0.0289
>
> 6) Sysreq-T during a freeze available on request.
> 7) .config or other info available on request
>
> Thank you for your help.
> PS: I'm not subscribed to the list, please CC: me if you answer.
>
> --
> Brice Figureau
>
>
> -
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@xxxxxxxxxxxxxxx
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/

-- 
-------------------------
Eric Bambach
Eric at cisu dot net
-------------------------
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/