runsolver Copyright (C) 2010 Olivier ROUSSEL This is runsolver version 3.2.9a (svn: 651) This program is distributed in the hope that it will be useful, but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for more details. command line: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand108.sarge-etch-lenny.cudf.sarge-etch-lenny.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge-etch-lenny/rand108.sarge-etch-lenny.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand108.sarge-etch-lenny.cudf.sarge-etch-lenny.result Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 seconds Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB Current StackSize limit: 8192 KiB [startup+0 s] /proc/loadavg: 0.84 0.93 0.72 4/39 9459 /proc/meminfo: memFree=69440/1048576 swapFree=2095372/2097144 [pid=9458] ppid=9457 vsize=2568 CPUtime=0 /proc/9458/stat : 9458 (cudf2pbo4trendy) S 9457 9458 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892305003 2629632 277 1283457024 134512640 135304128 4291821296 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9458/statm: 642 277 238 194 0 28 0 [pid=9459] ppid=9458 vsize=2044 CPUtime=0.01 /proc/9459/stat : 9459 (cudf_msu32) R 9458 9458 9023 34817 9081 4202496 305 0 0 0 1 0 0 0 25 0 1 0 892305003 2093056 198 1283457024 134512640 136125367 4289932720 18446744073709551615 135529576 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9459/statm: 511 198 141 394 0 115 0 [startup+0.125623 s] /proc/loadavg: 0.84 0.93 0.72 4/39 9459 /proc/meminfo: memFree=69440/1048576 swapFree=2095372/2097144 [pid=9458] ppid=9457 vsize=2568 CPUtime=0 /proc/9458/stat : 9458 (cudf2pbo4trendy) S 9457 9458 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892305003 2629632 277 1283457024 134512640 135304128 4291821296 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9458/statm: 642 277 238 194 0 28 0 [pid=9459] ppid=9458 vsize=7160 CPUtime=0.13 /proc/9459/stat : 9459 (cudf_msu32) R 9458 9458 9023 34817 9081 4202496 1596 0 0 0 12 1 0 0 25 0 1 0 892305003 7331840 1489 1283457024 134512640 136125367 4289932720 18446744073709551615 134718128 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9459/statm: 1790 1489 142 394 0 1394 0 Current children cumulated CPU time (s) 0.13 Current children cumulated vsize (KiB) 9728 [startup+0.205647 s] /proc/loadavg: 0.84 0.93 0.72 4/39 9459 /proc/meminfo: memFree=69440/1048576 swapFree=2095372/2097144 [pid=9458] ppid=9457 vsize=2568 CPUtime=0 /proc/9458/stat : 9458 (cudf2pbo4trendy) S 9457 9458 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892305003 2629632 277 1283457024 134512640 135304128 4291821296 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9458/statm: 642 277 238 194 0 28 0 [pid=9459] ppid=9458 vsize=9992 CPUtime=0.21 /proc/9459/stat : 9459 (cudf_msu32) R 9458 9458 9023 34817 9081 4202496 2321 0 0 0 20 1 0 0 25 0 1 0 892305003 10231808 2214 1283457024 134512640 136125367 4289932720 18446744073709551615 134738395 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9459/statm: 2498 2214 142 394 0 2102 0 Current children cumulated CPU time (s) 0.21 Current children cumulated vsize (KiB) 12560 [startup+0.305668 s] /proc/loadavg: 0.84 0.93 0.72 4/39 9459 /proc/meminfo: memFree=69440/1048576 swapFree=2095372/2097144 [pid=9458] ppid=9457 vsize=2568 CPUtime=0 /proc/9458/stat : 9458 (cudf2pbo4trendy) S 9457 9458 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892305003 2629632 277 1283457024 134512640 135304128 4291821296 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9458/statm: 642 277 238 194 0 28 0 [pid=9459] ppid=9458 vsize=13488 CPUtime=0.31 /proc/9459/stat : 9459 (cudf_msu32) R 9458 9458 9023 34817 9081 4202496 3179 0 0 0 29 2 0 0 25 0 1 0 892305003 13811712 3072 1283457024 134512640 136125367 4289932720 18446744073709551615 135293395 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9459/statm: 3372 3072 143 394 0 2976 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 16056 [startup+0.705765 s] /proc/loadavg: 0.84 0.93 0.72 4/39 9459 /proc/meminfo: memFree=69440/1048576 swapFree=2095372/2097144 [pid=9458] ppid=9457 vsize=2568 CPUtime=0 /proc/9458/stat : 9458 (cudf2pbo4trendy) S 9457 9458 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 892305003 2629632 277 1283457024 134512640 135304128 4291821296 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9458/statm: 642 277 238 194 0 28 0 [pid=9459] ppid=9458 vsize=25060 CPUtime=0.71 /proc/9459/stat : 9459 (cudf_msu32) R 9458 9458 9023 34817 9081 4202496 6081 0 0 0 67 4 0 0 25 0 1 0 892305003 25661440 5974 1283457024 134512640 136125367 4289932720 18446744073709551615 134675120 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/9459/statm: 6265 5974 153 394 0 5869 0 Current children cumulated CPU time (s) 0.71 Current children cumulated vsize (KiB) 27628 [startup+1.50596 s] /proc/loadavg: 0.84 0.93 0.72 2/40 9460 /proc/meminfo: memFree=33204/1048576 swapFree=2095372/2097144 [pid=9458] ppid=9457 vsize=2568 CPUtime=1.46 /proc/9458/stat : 9458 (cudf2pbo4trendy) S 9457 9458 9023 34817 9081 4202496 400 9357 0 0 0 0 114 32 20 0 1 0 892305003 2629632 280 1283457024 134512640 135304128 4291821296 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9458/statm: 642 280 241 194 0 28 0 Current children cumulated CPU time (s) 1.46 Current children cumulated vsize (KiB) 2568 [startup+3.11038 s] /proc/loadavg: 0.84 0.93 0.72 2/40 9461 /proc/meminfo: memFree=50936/1048576 swapFree=2095372/2097144 [pid=9458] ppid=9457 vsize=2568 CPUtime=1.46 /proc/9458/stat : 9458 (cudf2pbo4trendy) S 9457 9458 9023 34817 9081 4202496 400 9357 0 0 0 0 114 32 20 0 1 0 892305003 2629632 280 1283457024 134512640 135304128 4291821296 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9458/statm: 642 280 241 194 0 28 0 [pid=9461] ppid=9458 vsize=18164 CPUtime=1.57 /proc/9461/stat : 9461 (bmo-pblex32) R 9458 9458 9023 34817 9081 4202496 4878 0 0 0 110 47 0 0 25 0 1 0 892305149 18599936 4171 1283457024 134512640 135887319 4291989408 18446744073709551615 134624248 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9461/statm: 4541 4171 138 336 0 4203 0 Current children cumulated CPU time (s) 3.03 Current children cumulated vsize (KiB) 20732 [startup+6.31096 s] /proc/loadavg: 0.85 0.93 0.72 2/40 9461 /proc/meminfo: memFree=45108/1048576 swapFree=2095372/2097144 [pid=9458] ppid=9457 vsize=2568 CPUtime=1.46 /proc/9458/stat : 9458 (cudf2pbo4trendy) S 9457 9458 9023 34817 9081 4202496 400 9357 0 0 0 0 114 32 20 0 1 0 892305003 2629632 280 1283457024 134512640 135304128 4291821296 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9458/statm: 642 280 241 194 0 28 0 [pid=9461] ppid=9458 vsize=29108 CPUtime=4.78 /proc/9461/stat : 9461 (bmo-pblex32) R 9458 9458 9023 34817 9081 4202496 9546 0 0 0 394 84 0 0 25 0 1 0 892305149 29806592 6932 1283457024 134512640 135887319 4291989408 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9461/statm: 7277 6932 144 336 0 6939 0 Current children cumulated CPU time (s) 6.24 Current children cumulated vsize (KiB) 31676 [startup+12.7122 s] /proc/loadavg: 0.87 0.93 0.72 2/40 9461 /proc/meminfo: memFree=39652/1048576 swapFree=2095372/2097144 [pid=9458] ppid=9457 vsize=2568 CPUtime=1.46 /proc/9458/stat : 9458 (cudf2pbo4trendy) S 9457 9458 9023 34817 9081 4202496 400 9357 0 0 0 0 114 32 20 0 1 0 892305003 2629632 280 1283457024 134512640 135304128 4291821296 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9458/statm: 642 280 241 194 0 28 0 [pid=9461] ppid=9458 vsize=29108 CPUtime=11.17 /proc/9461/stat : 9461 (bmo-pblex32) R 9458 9458 9023 34817 9081 4202496 9546 0 0 0 1024 93 0 0 25 0 1 0 892305149 29806592 6932 1283457024 134512640 135887319 4291989408 18446744073709551615 134526502 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9461/statm: 7277 6932 144 336 0 6939 0 Current children cumulated CPU time (s) 12.63 Current children cumulated vsize (KiB) 31676 [startup+25.5058 s] /proc/loadavg: 0.89 0.94 0.73 2/40 9461 /proc/meminfo: memFree=31344/1048576 swapFree=2095372/2097144 [pid=9458] ppid=9457 vsize=2568 CPUtime=1.46 /proc/9458/stat : 9458 (cudf2pbo4trendy) S 9457 9458 9023 34817 9081 4202496 400 9357 0 0 0 0 114 32 20 0 1 0 892305003 2629632 280 1283457024 134512640 135304128 4291821296 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9458/statm: 642 280 241 194 0 28 0 [pid=9461] ppid=9458 vsize=37728 CPUtime=23.9 /proc/9461/stat : 9461 (bmo-pblex32) R 9458 9458 9023 34817 9081 4202496 13108 0 0 0 2220 170 0 0 25 0 1 0 892305149 38633472 9089 1283457024 134512640 135887319 4291989408 18446744073709551615 134525200 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9461/statm: 9432 9089 144 336 0 9094 0 Current children cumulated CPU time (s) 25.36 Current children cumulated vsize (KiB) 40296 [startup+51.1114 s] /proc/loadavg: 0.93 0.94 0.73 2/40 9461 /proc/meminfo: memFree=28368/1048576 swapFree=2095372/2097144 [pid=9458] ppid=9457 vsize=2568 CPUtime=1.46 /proc/9458/stat : 9458 (cudf2pbo4trendy) S 9457 9458 9023 34817 9081 4202496 400 9357 0 0 0 0 114 32 20 0 1 0 892305003 2629632 280 1283457024 134512640 135304128 4291821296 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9458/statm: 642 280 241 194 0 28 0 [pid=9461] ppid=9458 vsize=40476 CPUtime=49.49 /proc/9461/stat : 9461 (bmo-pblex32) R 9458 9458 9023 34817 9081 4202496 13966 0 0 0 4752 197 0 0 25 0 1 0 892305149 41447424 9786 1283457024 134512640 135887319 4291989408 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9461/statm: 10119 9786 144 336 0 9781 0 Current children cumulated CPU time (s) 50.95 Current children cumulated vsize (KiB) 43044 [startup+102.302 s] /proc/loadavg: 0.97 0.95 0.74 2/40 9461 /proc/meminfo: memFree=26756/1048576 swapFree=2095372/2097144 [pid=9458] ppid=9457 vsize=2568 CPUtime=1.46 /proc/9458/stat : 9458 (cudf2pbo4trendy) S 9457 9458 9023 34817 9081 4202496 400 9357 0 0 0 0 114 32 20 0 1 0 892305003 2629632 280 1283457024 134512640 135304128 4291821296 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9458/statm: 642 280 241 194 0 28 0 [pid=9461] ppid=9458 vsize=41932 CPUtime=100.65 /proc/9461/stat : 9461 (bmo-pblex32) R 9458 9458 9023 34817 9081 4202496 14338 0 0 0 9865 200 0 0 25 0 1 0 892305149 42938368 10145 1283457024 134512640 135887319 4291989408 18446744073709551615 134603644 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9461/statm: 10483 10145 144 336 0 10145 0 Current children cumulated CPU time (s) 102.11 Current children cumulated vsize (KiB) 44500 [startup+162.306 s] /proc/loadavg: 0.99 0.95 0.75 2/40 9461 /proc/meminfo: memFree=26260/1048576 swapFree=2095372/2097144 [pid=9458] ppid=9457 vsize=2568 CPUtime=1.46 /proc/9458/stat : 9458 (cudf2pbo4trendy) S 9457 9458 9023 34817 9081 4202496 400 9357 0 0 0 0 114 32 20 0 1 0 892305003 2629632 280 1283457024 134512640 135304128 4291821296 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9458/statm: 642 280 241 194 0 28 0 [pid=9461] ppid=9458 vsize=42328 CPUtime=160.62 /proc/9461/stat : 9461 (bmo-pblex32) R 9458 9458 9023 34817 9081 4202496 14453 0 0 0 15862 200 0 0 25 0 1 0 892305149 43343872 10249 1283457024 134512640 135887319 4291989408 18446744073709551615 134603576 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9461/statm: 10582 10249 144 336 0 10244 0 Current children cumulated CPU time (s) 162.08 Current children cumulated vsize (KiB) 44896 [startup+222.31 s] /proc/loadavg: 0.99 0.96 0.76 2/40 9461 /proc/meminfo: memFree=25268/1048576 swapFree=2095372/2097144 [pid=9458] ppid=9457 vsize=2568 CPUtime=1.46 /proc/9458/stat : 9458 (cudf2pbo4trendy) S 9457 9458 9023 34817 9081 4202496 400 9357 0 0 0 0 114 32 20 0 1 0 892305003 2629632 280 1283457024 134512640 135304128 4291821296 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9458/statm: 642 280 241 194 0 28 0 [pid=9461] ppid=9458 vsize=43256 CPUtime=220.57 /proc/9461/stat : 9461 (bmo-pblex32) R 9458 9458 9023 34817 9081 4202496 14671 0 0 0 21852 205 0 0 25 0 1 0 892305149 44294144 10461 1283457024 134512640 135887319 4291989408 18446744073709551615 134526753 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9461/statm: 10814 10461 144 336 0 10476 0 Current children cumulated CPU time (s) 222.03 Current children cumulated vsize (KiB) 45824 [startup+282.31 s] /proc/loadavg: 0.99 0.96 0.78 2/40 9461 /proc/meminfo: memFree=24772/1048576 swapFree=2095372/2097144 [pid=9458] ppid=9457 vsize=2568 CPUtime=1.46 /proc/9458/stat : 9458 (cudf2pbo4trendy) S 9457 9458 9023 34817 9081 4202496 400 9357 0 0 0 0 114 32 20 0 1 0 892305003 2629632 280 1283457024 134512640 135304128 4291821296 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9458/statm: 642 280 241 194 0 28 0 [pid=9461] ppid=9458 vsize=43652 CPUtime=280.56 /proc/9461/stat : 9461 (bmo-pblex32) R 9458 9458 9023 34817 9081 4202496 14776 0 0 0 27851 205 0 0 25 0 1 0 892305149 44699648 10566 1283457024 134512640 135887319 4291989408 18446744073709551615 134526502 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9461/statm: 10913 10566 144 336 0 10575 0 Current children cumulated CPU time (s) 282.02 Current children cumulated vsize (KiB) 46220 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.312 s] /proc/loadavg: 0.99 0.96 0.78 2/40 9461 /proc/meminfo: memFree=24772/1048576 swapFree=2095372/2097144 [pid=9458] ppid=9457 vsize=2568 CPUtime=1.46 /proc/9458/stat : 9458 (cudf2pbo4trendy) S 9457 9458 9023 34817 9081 4202496 400 9357 0 0 0 0 114 32 20 0 1 0 892305003 2629632 280 1283457024 134512640 135304128 4291821296 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/9458/statm: 642 280 241 194 0 28 0 [pid=9461] ppid=9458 vsize=43652 CPUtime=288.56 /proc/9461/stat : 9461 (bmo-pblex32) R 9458 9458 9023 34817 9081 4202496 14785 0 0 0 28651 205 0 0 25 0 1 0 892305149 44699648 10575 1283457024 134512640 135887319 4291989408 18446744073709551615 134603576 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/9461/statm: 10913 10575 144 336 0 10575 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 46220 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples Child status: 0 Real time (s): 290.39 CPU time (s): 290.106 CPU user time (s): 287.714 CPU system time (s): 2.39215 CPU usage (%): 99.9021 Max. virtual memory (cumulated for all children) (KiB): 46220 getrusage(RUSAGE_CHILDREN,...) data: user time used= 287.714 system time used= 2.39215 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 26475 page faults= 0 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 14 involuntary context switches= 8896 runsolver used 0 second user time and 0 second system time The end