Bugzilla – Bug 636290
The kernel reports wrong process user/sys time
Last modified: 2010-11-07 14:42:31 UTC
User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9.2.8) Gecko/20100723 SUSE/3.6.8-0.1.1 Firefox/3.6.8 We have an algorithm implemented that does extensive calculations with almost no syscalls. The kernel however reports it as system time: $ time ./dimacs-solver i_n13.dimacs.int Problem type: min Num of nodes: 8181 Num of arcs: 739733 Sum of supply values: 0 GEQ supply contraints are used for NetworkSimplex Read the file: u: 1.1s, s: 0.06s, cu: 0s, cs: 0s, real: 1.20954s Setup NetworkSimplex class: u: 0.04s, s: 0.03s, cu: 0s, cs: 0s, real: 0.0795369s Run NetworkSimplex: u: 13.83s, s: 189.24s, cu: 0s, cs: 0s, real: 204.291s Feasible flow: found Min flow cost: 847714917290 real 3m25.757s user 0m14.987s sys 3m9.338s Above, the "Run NetworkSimplex" line shows the part of the execution that makes no system call at all; still it is reported as being on the system level. The output of strace confirms this clearly: $ strace -tt -T ./build/tools/dimacs-solver i_n13.dimacs.int [...] 16:58:22.722844 gettimeofday({1283353102, 722869}, NULL) = 0 <0.000031> 16:58:22.722950 times({tms_utime=115, tms_stime=9, tms_cutime=0, tms_cstime=0}) = 429597560 <0.000033> 16:58:22.745973 brk(0x8155000) = 0x8155000 <0.000021> 17:01:48.960355 gettimeofday({1283353308, 960428}, NULL) = 0 <0.000048> 17:01:48.960523 times({tms_utime=1801, tms_stime=18819, tms_cutime=0, tms_cstime=0}) = 429618181 <0.000041> 17:01:48.960641 write(2, "Run NetworkSimplex: ", 20Run NetworkSimplex: ) = 20 <0.000042> 17:01:48.960748 write(2, "u: ", 3u: ) = 3 <0.000118> 17:01:48.960969 write(2, "16.86", 516.86) = 5 <0.000047> 17:01:48.961087 write(2, "s, s: ", 6s, s: ) = 6 <0.000045> 17:01:48.961203 write(2, "188.1", 5188.1) = 5 <0.000039> 17:01:48.961308 write(2, "s, cu: ", 7s, cu: ) = 7 <0.000032> 17:01:48.961402 write(2, "0", 10) = 1 <0.000034> 17:01:48.961491 write(2, "s, cs: ", 7s, cs: ) = 7 <0.000034> 17:01:48.961584 write(2, "0", 10) = 1 <0.000033> 17:01:48.961728 write(2, "s, real: ", 9s, real: ) = 9 <0.000036> 17:01:48.961830 write(2, "206.238", 7206.238) = 7 <0.000038> 17:01:48.961934 write(2, "s", 1s) = 1 <0.000041> 17:01:48.962033 write(2, "\n\n", 2 [...] The source code of dimacs_solver is available at http://lemon.cs.elte.hu/hg/lemon-main, the problem is reproducible at least with g++-4.5 and g++-4.3 Reproducible: Always Steps to Reproduce: 1. Download http://lime.cs.elte.hu/~alpar/dimacs-solver and http://lime.cs.elte.hu/~alpar/i_n13.dimacs.int 2. Run $ time ./dimacs-solver i_n13.dimacs.int Actual Results: Problem type: min Num of nodes: 8181 Num of arcs: 739733 Sum of supply values: 0 GEQ supply contraints are used for NetworkSimplex Read the file: u: 1.1s, s: 0.06s, cu: 0s, cs: 0s, real: 1.20954s Setup NetworkSimplex class: u: 0.04s, s: 0.03s, cu: 0s, cs: 0s, real: 0.0795369s Run NetworkSimplex: u: 13.83s, s: 189.24s, cu: 0s, cs: 0s, real: 204.291s Feasible flow: found Min flow cost: 847714917290 real 3m25.757s user 0m14.987s sys 3m9.338s Expected Results: Something like: Problem type: min Num of nodes: 8181 Num of arcs: 739733 Sum of supply values: 0 GEQ supply contraints are used for NetworkSimplex Read the file: u: 1.1s, s: 0.06s, cu: 0s, cs: 0s, real: 1.20954s Setup NetworkSimplex class: u: 0.04s, s: 0.03s, cu: 0s, cs: 0s, real: 0.0795369s Run NetworkSimplex: u: 203.04s, s: 0.03s, cu: 0s, cs: 0s, real: 204.291s Feasible flow: found Min flow cost: 847714917290 real 3m25.757s user 3m22.338s sys 0m1.987s
The problem still persist with the latest kernel update: $ uname -a Linux xxx.xxx 2.6.34.4-0.1-desktop #1 SMP PREEMPT 2010-08-20 19:21:29 +0200 i686 i686 i386 GNU/Linux Btw, when the algorithm is running, the system monitors (e.g. top and the gnome sysmon applet) correctly report 1 processor full usage on user level.
Hmm, I cannot reproduce on 64bit. So this looks like 32bit specific: linux-b984:/tmp # uname -a Linux linux-b984 2.6.34.4-0.1-desktop #1 SMP PREEMPT 2010-08-20 19:21:29 +0200 x86_64 x86_64 x86_64 GNU/Linux linux-b984:/tmp # time ./dimacs-solver i_n13.dimacs.int Problem type: min ... Min flow cost: 847714917290 real 2m4.846s user 2m4.477s sys 0m0.184s
Ok, it's reproducible on 32bit. Could you somehow reduce the sample file so that it doesn't take minutes to finish? ~10s would be enough, I think.
Closed due to lack of response.