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/rand550.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze-sid/rand550.sarge-etch-lenny-squeeze-sid.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand550.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.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.99 0.97 0.91 3/39 11377 /proc/meminfo: memFree=110708/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2568 CPUtime=0 /proc/11376/stat : 11376 (cudf2pbo4trendy) R 11375 11376 9023 34817 9081 4202496 363 0 0 0 0 0 0 0 25 0 1 0 893510273 2629632 277 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0 /proc/11376/statm: 642 277 238 194 0 28 0 [pid=11377] ppid=11376 vsize=2568 CPUtime=0 /proc/11377/stat : 11377 (cudf2pbo4trendy) R 11376 11376 9023 34817 9081 4202560 0 0 0 0 0 0 0 0 25 0 1 0 893510273 2629632 39 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0 /proc/11377/statm: 642 39 0 194 0 28 0 [startup+0.153462 s] /proc/loadavg: 0.99 0.97 0.91 3/39 11377 /proc/meminfo: memFree=110708/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2568 CPUtime=0 /proc/11376/stat : 11376 (cudf2pbo4trendy) S 11375 11376 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 893510273 2629632 277 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11376/statm: 642 277 238 194 0 28 0 [pid=11377] ppid=11376 vsize=8312 CPUtime=0.14 /proc/11377/stat : 11377 (cudf_msu32) R 11376 11376 9023 34817 9081 4202496 1889 0 0 0 14 0 0 0 25 0 1 0 893510273 8511488 1782 1283457024 134512640 136125367 4289561904 18446744073709551615 134717796 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11377/statm: 2078 1782 142 394 0 1682 0 Current children cumulated CPU time (s) 0.14 Current children cumulated vsize (KiB) 10880 [startup+0.203479 s] /proc/loadavg: 0.99 0.97 0.91 3/39 11377 /proc/meminfo: memFree=110708/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2568 CPUtime=0 /proc/11376/stat : 11376 (cudf2pbo4trendy) S 11375 11376 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 893510273 2629632 277 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11376/statm: 642 277 238 194 0 28 0 [pid=11377] ppid=11376 vsize=10292 CPUtime=0.19 /proc/11377/stat : 11377 (cudf_msu32) R 11376 11376 9023 34817 9081 4202496 2368 0 0 0 19 0 0 0 25 0 1 0 893510273 10539008 2261 1283457024 134512640 136125367 4289561904 18446744073709551615 134718199 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11377/statm: 2573 2261 142 394 0 2177 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 12860 [startup+0.313489 s] /proc/loadavg: 0.99 0.97 0.91 3/39 11377 /proc/meminfo: memFree=110708/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2568 CPUtime=0 /proc/11376/stat : 11376 (cudf2pbo4trendy) S 11375 11376 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 893510273 2629632 277 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11376/statm: 642 277 238 194 0 28 0 [pid=11377] ppid=11376 vsize=14052 CPUtime=0.3 /proc/11377/stat : 11377 (cudf_msu32) R 11376 11376 9023 34817 9081 4202496 3315 0 0 0 30 0 0 0 25 0 1 0 893510273 14389248 3208 1283457024 134512640 136125367 4289561904 18446744073709551615 134717805 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11377/statm: 3513 3208 143 394 0 3117 0 Current children cumulated CPU time (s) 0.3 Current children cumulated vsize (KiB) 16620 [startup+0.71357 s] /proc/loadavg: 0.99 0.97 0.91 3/39 11377 /proc/meminfo: memFree=110708/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2568 CPUtime=0 /proc/11376/stat : 11376 (cudf2pbo4trendy) S 11375 11376 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 893510273 2629632 277 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11376/statm: 642 277 238 194 0 28 0 [pid=11377] ppid=11376 vsize=26128 CPUtime=0.71 /proc/11377/stat : 11377 (cudf_msu32) R 11376 11376 9023 34817 9081 4202496 6350 0 0 0 69 2 0 0 25 0 1 0 893510273 26755072 6243 1283457024 134512640 136125367 4289561904 18446744073709551615 134717908 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11377/statm: 6532 6243 143 394 0 6136 0 Current children cumulated CPU time (s) 0.71 Current children cumulated vsize (KiB) 28696 [startup+1.51376 s] /proc/loadavg: 0.99 0.97 0.91 2/40 11378 /proc/meminfo: memFree=77828/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2568 CPUtime=0 /proc/11376/stat : 11376 (cudf2pbo4trendy) S 11375 11376 9023 34817 9081 4202496 380 0 0 0 0 0 0 0 25 0 1 0 893510273 2629632 277 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11376/statm: 642 277 238 194 0 28 0 [pid=11377] ppid=11376 vsize=52500 CPUtime=1.51 /proc/11377/stat : 11377 (cudf_msu32) R 11376 11376 9023 34817 9081 4202496 12995 0 0 0 141 10 0 0 25 0 1 0 893510273 53760000 12838 1283457024 134512640 136125367 4289561904 18446744073709551615 134610136 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11377/statm: 13125 12838 160 394 0 12729 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 55068 [startup+3.111 s] /proc/loadavg: 0.99 0.97 0.91 2/40 11378 /proc/meminfo: memFree=51912/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2568 CPUtime=2.41 /proc/11376/stat : 11376 (cudf2pbo4trendy) S 11375 11376 9023 34817 9081 4202496 399 14871 0 0 0 0 190 51 18 0 1 0 893510273 2629632 280 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11376/statm: 642 280 241 194 0 28 0 Current children cumulated CPU time (s) 2.41 Current children cumulated vsize (KiB) 2568 heavy processes: [startup+6.30549 s] /proc/loadavg: 0.99 0.97 0.91 2/40 11379 /proc/meminfo: memFree=82168/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2568 CPUtime=2.41 /proc/11376/stat : 11376 (cudf2pbo4trendy) S 11375 11376 9023 34817 9081 4202496 399 14871 0 0 0 0 190 51 18 0 1 0 893510273 2629632 280 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11376/statm: 642 280 241 194 0 28 0 [pid=11379] ppid=11376 vsize=28228 CPUtime=3.72 /proc/11379/stat : 11379 (bmo-pblex32) R 11376 11376 9023 34817 9081 4202496 7436 0 0 0 286 86 0 0 25 0 1 0 893510517 28905472 6578 1283457024 134512640 135887319 4290885248 18446744073709551615 134525478 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11379/statm: 7057 6578 138 336 0 6719 0 Current children cumulated CPU time (s) 6.13 Current children cumulated vsize (KiB) 30796 [startup+12.7072 s] /proc/loadavg: 0.99 0.97 0.91 2/40 11379 /proc/meminfo: memFree=57120/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2568 CPUtime=2.41 /proc/11376/stat : 11376 (cudf2pbo4trendy) S 11375 11376 9023 34817 9081 4202496 399 14871 0 0 0 0 190 51 18 0 1 0 893510273 2629632 280 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11376/statm: 642 280 241 194 0 28 0 [pid=11379] ppid=11376 vsize=52484 CPUtime=10.11 /proc/11379/stat : 11379 (bmo-pblex32) R 11376 11376 9023 34817 9081 4202496 18102 0 0 0 803 208 0 0 25 0 1 0 893510517 53743616 12684 1283457024 134512640 135887319 4290885248 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11379/statm: 13121 12684 144 336 0 12783 0 Current children cumulated CPU time (s) 12.52 Current children cumulated vsize (KiB) 55052 [startup+25.5108 s] /proc/loadavg: 0.99 0.97 0.91 2/40 11379 /proc/meminfo: memFree=50176/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2568 CPUtime=2.41 /proc/11376/stat : 11376 (cudf2pbo4trendy) S 11375 11376 9023 34817 9081 4202496 399 14871 0 0 0 0 190 51 18 0 1 0 893510273 2629632 280 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11376/statm: 642 280 241 194 0 28 0 [pid=11379] ppid=11376 vsize=60048 CPUtime=22.8 /proc/11379/stat : 11379 (bmo-pblex32) R 11376 11376 9023 34817 9081 4202496 20100 0 0 0 1961 319 0 0 25 0 1 0 893510517 61489152 14581 1283457024 134512640 135887319 4290885248 18446744073709551615 134605912 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11379/statm: 15012 14581 144 336 0 14674 0 Current children cumulated CPU time (s) 25.21 Current children cumulated vsize (KiB) 62616 [startup+51.1071 s] /proc/loadavg: 0.99 0.97 0.91 2/40 11379 /proc/meminfo: memFree=48688/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2568 CPUtime=2.41 /proc/11376/stat : 11376 (cudf2pbo4trendy) S 11375 11376 9023 34817 9081 4202496 399 14871 0 0 0 0 190 51 18 0 1 0 893510273 2629632 280 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11376/statm: 642 280 241 194 0 28 0 [pid=11379] ppid=11376 vsize=61504 CPUtime=48.38 /proc/11379/stat : 11379 (bmo-pblex32) R 11376 11376 9023 34817 9081 4202496 20465 0 0 0 4518 320 0 0 25 0 1 0 893510517 62980096 14922 1283457024 134512640 135887319 4290885248 18446744073709551615 134603339 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11379/statm: 15376 14922 144 336 0 15038 0 Current children cumulated CPU time (s) 50.79 Current children cumulated vsize (KiB) 64072 [startup+102.31 s] /proc/loadavg: 0.99 0.97 0.91 2/40 11379 /proc/meminfo: memFree=45092/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2568 CPUtime=2.41 /proc/11376/stat : 11376 (cudf2pbo4trendy) S 11375 11376 9023 34817 9081 4202496 399 14871 0 0 0 0 190 51 18 0 1 0 893510273 2629632 280 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11376/statm: 642 280 241 194 0 28 0 [pid=11379] ppid=11376 vsize=65068 CPUtime=99.55 /proc/11379/stat : 11379 (bmo-pblex32) R 11376 11376 9023 34817 9081 4202496 21371 0 0 0 9634 321 0 0 25 0 1 0 893510517 66629632 15812 1283457024 134512640 135887319 4290885248 18446744073709551615 134603576 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11379/statm: 16267 15812 144 336 0 15929 0 Current children cumulated CPU time (s) 101.96 Current children cumulated vsize (KiB) 67636 [startup+162.307 s] /proc/loadavg: 0.99 0.97 0.91 2/40 11379 /proc/meminfo: memFree=42364/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2568 CPUtime=2.41 /proc/11376/stat : 11376 (cudf2pbo4trendy) S 11375 11376 9023 34817 9081 4202496 399 14871 0 0 0 0 190 51 18 0 1 0 893510273 2629632 280 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11376/statm: 642 280 241 194 0 28 0 [pid=11379] ppid=11376 vsize=67576 CPUtime=159.49 /proc/11379/stat : 11379 (bmo-pblex32) R 11376 11376 9023 34817 9081 4202496 22038 0 0 0 15625 324 0 0 25 0 1 0 893510517 69197824 16456 1283457024 134512640 135887319 4290885248 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11379/statm: 16894 16456 144 336 0 16556 0 Current children cumulated CPU time (s) 161.9 Current children cumulated vsize (KiB) 70144 [startup+222.31 s] /proc/loadavg: 0.99 0.97 0.91 2/40 11379 /proc/meminfo: memFree=39264/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2568 CPUtime=2.41 /proc/11376/stat : 11376 (cudf2pbo4trendy) S 11375 11376 9023 34817 9081 4202496 399 14871 0 0 0 0 190 51 18 0 1 0 893510273 2629632 280 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11376/statm: 642 280 241 194 0 28 0 [pid=11379] ppid=11376 vsize=70764 CPUtime=219.48 /proc/11379/stat : 11379 (bmo-pblex32) R 11376 11376 9023 34817 9081 4202496 22838 0 0 0 21619 329 0 0 25 0 1 0 893510517 72462336 17235 1283457024 134512640 135887319 4290885248 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11379/statm: 17691 17235 144 336 0 17353 0 Current children cumulated CPU time (s) 221.89 Current children cumulated vsize (KiB) 73332 [startup+282.314 s] /proc/loadavg: 0.99 0.97 0.91 2/40 11379 /proc/meminfo: memFree=36412/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2568 CPUtime=2.41 /proc/11376/stat : 11376 (cudf2pbo4trendy) S 11375 11376 9023 34817 9081 4202496 399 14871 0 0 0 0 190 51 18 0 1 0 893510273 2629632 280 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11376/statm: 642 280 241 194 0 28 0 [pid=11379] ppid=11376 vsize=73496 CPUtime=279.44 /proc/11379/stat : 11379 (bmo-pblex32) R 11376 11376 9023 34817 9081 4202496 23570 0 0 0 27614 330 0 0 25 0 1 0 893510517 75259904 17929 1283457024 134512640 135887319 4290885248 18446744073709551615 134603443 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11379/statm: 18374 17929 144 336 0 18036 0 Current children cumulated CPU time (s) 281.85 Current children cumulated vsize (KiB) 76064 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.515 s] /proc/loadavg: 0.99 0.97 0.91 2/40 11379 /proc/meminfo: memFree=36288/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2568 CPUtime=2.41 /proc/11376/stat : 11376 (cudf2pbo4trendy) S 11375 11376 9023 34817 9081 4202496 399 14871 0 0 0 0 190 51 18 0 1 0 893510273 2629632 280 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11376/statm: 642 280 241 194 0 28 0 [pid=11379] ppid=11376 vsize=73628 CPUtime=287.64 /proc/11379/stat : 11379 (bmo-pblex32) R 11376 11376 9023 34817 9081 4202496 23602 0 0 0 28434 330 0 0 25 0 1 0 893510517 75395072 17961 1283457024 134512640 135887319 4290885248 18446744073709551615 134526944 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11379/statm: 18407 17961 144 336 0 18069 0 Current children cumulated CPU time (s) 290.05 Current children cumulated vsize (KiB) 76196 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples [startup+290.626 s] /proc/loadavg: 0.99 0.97 0.91 2/40 11379 /proc/meminfo: memFree=36288/1048576 swapFree=2095372/2097144 [pid=11376] ppid=11375 vsize=2576 CPUtime=290.07 /proc/11376/stat : 11376 (cudf2pbo4trendy) S 11375 11376 9023 34817 9081 4202496 440 38890 0 0 0 0 28624 383 20 0 1 0 893510273 2637824 286 1283457024 134512640 135304128 4292997088 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11376/statm: 644 286 245 194 0 30 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 2576 Child status: 0 Real time (s): 290.627 CPU time (s): 290.17 CPU user time (s): 286.314 CPU system time (s): 3.85624 CPU usage (%): 99.8426 Max. virtual memory (cumulated for all children) (KiB): 76196 getrusage(RUSAGE_CHILDREN,...) data: user time used= 286.314 system time used= 3.85624 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 41122 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= 23 involuntary context switches= 8339 runsolver used 0 second user time and 0.008 second system time The end