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/201012070034/aspcud-trendy-1.3/rand494.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand494.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand494.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.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: 1.02 1.04 1.00 1/40 17469 /proc/meminfo: memFree=781140/1048576 swapFree=2080268/2097144 [pid=17469] ppid=17468 vsize=3020 CPUtime=0 /proc/17469/stat : 17469 (runsolver) D 17468 17469 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 25 0 1 0 880906444 3092480 93 1283457024 134512640 134586868 4292615856 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/17469/statm: 755 93 62 19 0 53 0 [startup+0.20117 s] /proc/loadavg: 1.02 1.04 1.00 1/40 17469 /proc/meminfo: memFree=781140/1048576 swapFree=2080268/2097144 [pid=17469] ppid=17468 vsize=2596 CPUtime=0 /proc/17469/stat : 17469 (aspcud-trendy-1) S 17468 17469 4159 34819 4229 4202496 622 2217 0 3 0 0 0 0 25 0 1 0 880906444 2658304 299 1283457024 134512640 135304128 4288908320 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17469/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.305103 s] /proc/loadavg: 1.02 1.04 1.00 1/40 17469 /proc/meminfo: memFree=781140/1048576 swapFree=2080268/2097144 [pid=17469] ppid=17468 vsize=2596 CPUtime=0 /proc/17469/stat : 17469 (aspcud-trendy-1) S 17468 17469 4159 34819 4229 4202496 622 2217 0 3 0 0 0 0 25 0 1 0 880906444 2658304 299 1283457024 134512640 135304128 4288908320 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17469/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.411714 s] /proc/loadavg: 1.02 1.04 1.00 1/40 17469 /proc/meminfo: memFree=781140/1048576 swapFree=2080268/2097144 [pid=17469] ppid=17468 vsize=2596 CPUtime=0 /proc/17469/stat : 17469 (aspcud-trendy-1) S 17468 17469 4159 34819 4229 4202496 622 2217 0 3 0 0 0 0 25 0 1 0 880906444 2658304 299 1283457024 134512640 135304128 4288908320 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17469/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.711783 s] /proc/loadavg: 1.02 1.04 1.00 1/40 17469 /proc/meminfo: memFree=781140/1048576 swapFree=2080268/2097144 [pid=17469] ppid=17468 vsize=2596 CPUtime=0 /proc/17469/stat : 17469 (aspcud-trendy-1) S 17468 17469 4159 34819 4229 4202496 622 2217 0 3 0 0 0 0 25 0 1 0 880906444 2658304 299 1283457024 134512640 135304128 4288908320 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17469/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.512 s] /proc/loadavg: 1.02 1.04 1.00 2/44 17483 /proc/meminfo: memFree=740596/1048576 swapFree=2080268/2097144 [pid=17469] ppid=17468 vsize=2596 CPUtime=0 /proc/17469/stat : 17469 (aspcud-trendy-1) S 17468 17469 4159 34819 4229 4202496 622 2217 0 3 0 0 0 0 25 0 1 0 880906444 2658304 299 1283457024 134512640 135304128 4288908320 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17469/statm: 649 299 253 194 0 35 0 [pid=17481] ppid=17469 vsize=2268 CPUtime=0 /proc/17481/stat : 17481 (clasp) S 17469 17469 4159 34819 4229 4202496 408 0 18 0 0 0 0 0 18 0 1 0 880906448 2322432 295 1283457024 134512640 136223643 4288716000 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/17481/statm: 567 295 173 418 0 147 0 [pid=17482] ppid=17469 vsize=3180 CPUtime=0.01 /proc/17482/stat : 17482 (gringo) S 17469 17469 4159 34819 4229 4202496 526 0 22 0 1 0 0 0 18 0 1 0 880906448 3256320 418 1283457024 134512640 136959103 4292778080 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/17482/statm: 795 418 247 598 0 194 0 [pid=17483] ppid=17469 vsize=43452 CPUtime=1.26 /proc/17483/stat : 17483 (cudf2lp) R 17469 17469 4159 34819 4229 4202496 14007 0 14 0 118 8 0 0 25 0 1 0 880906448 44494848 10657 1283457024 134512640 135749571 4287222768 18446744073709551615 135153664 0 0 6 0 0 0 0 17 0 0 0 0 /proc/17483/statm: 10863 10657 129 302 0 10559 0 Current children cumulated CPU time (s) 1.27 Current children cumulated vsize (KiB) 51496 [startup+3.11352 s] /proc/loadavg: 1.02 1.04 1.00 3/44 17483 /proc/meminfo: memFree=707556/1048576 swapFree=2080268/2097144 [pid=17469] ppid=17468 vsize=2596 CPUtime=1.51 /proc/17469/stat : 17469 (aspcud-trendy-1) S 17468 17469 4159 34819 4229 4202496 623 16227 0 18 0 0 141 10 18 0 1 0 880906444 2658304 299 1283457024 134512640 135304128 4288908320 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17469/statm: 649 299 253 194 0 35 0 [pid=17481] ppid=17469 vsize=27052 CPUtime=0.13 /proc/17481/stat : 17481 (clasp) R 17469 17469 4159 34819 4229 4202496 7587 0 18 0 10 3 0 0 18 0 1 0 880906448 27701248 6410 1283457024 134512640 136223643 4288716000 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17481/statm: 6763 6410 174 418 0 6343 0 [pid=17482] ppid=17469 vsize=43812 CPUtime=1.19 /proc/17482/stat : 17482 (gringo) R 17469 17469 4159 34819 4229 4202496 13101 0 22 0 115 4 0 0 18 0 1 0 880906448 44863488 8798 1283457024 134512640 136959103 4292778080 18446744073709551615 136227576 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17482/statm: 10953 8798 256 598 0 10352 0 Current children cumulated CPU time (s) 2.83 Current children cumulated vsize (KiB) 73460 [startup+6.31465 s] /proc/loadavg: 1.02 1.04 1.00 2/42 17483 /proc/meminfo: memFree=724704/1048576 swapFree=2080268/2097144 [pid=17469] ppid=17468 vsize=2596 CPUtime=3.48 /proc/17469/stat : 17469 (aspcud-trendy-1) S 17468 17469 4159 34819 4229 4202496 623 34742 0 40 0 0 330 18 18 0 1 0 880906444 2658304 299 1283457024 134512640 135304128 4288908320 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17469/statm: 649 299 253 194 0 35 0 [pid=17481] ppid=17469 vsize=55880 CPUtime=2.55 /proc/17481/stat : 17481 (clasp) R 17469 17469 4159 34819 4229 4202496 16176 0 19 0 246 9 0 0 21 0 1 0 880906448 57221120 12895 1283457024 134512640 136223643 4288716000 18446744073709551615 134870731 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17481/statm: 13970 12895 223 418 0 13550 0 Current children cumulated CPU time (s) 6.03 Current children cumulated vsize (KiB) 58476 [startup+12.7067 s] /proc/loadavg: 1.02 1.04 1.00 2/42 17483 /proc/meminfo: memFree=715164/1048576 swapFree=2080268/2097144 [pid=17469] ppid=17468 vsize=2596 CPUtime=3.48 /proc/17469/stat : 17469 (aspcud-trendy-1) S 17468 17469 4159 34819 4229 4202496 623 34742 0 40 0 0 330 18 18 0 1 0 880906444 2658304 299 1283457024 134512640 135304128 4288908320 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17469/statm: 649 299 253 194 0 35 0 [pid=17481] ppid=17469 vsize=71108 CPUtime=8.94 /proc/17481/stat : 17481 (clasp) R 17469 17469 4159 34819 4229 4202496 19979 0 19 0 884 10 0 0 25 0 1 0 880906448 72814592 16698 1283457024 134512640 136223643 4288716000 18446744073709551615 134704909 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17481/statm: 17777 16698 225 418 0 17357 0 Current children cumulated CPU time (s) 12.42 Current children cumulated vsize (KiB) 73704 [startup+25.5102 s] /proc/loadavg: 1.01 1.04 1.00 2/42 17483 /proc/meminfo: memFree=671640/1048576 swapFree=2080268/2097144 [pid=17469] ppid=17468 vsize=2596 CPUtime=3.48 /proc/17469/stat : 17469 (aspcud-trendy-1) S 17468 17469 4159 34819 4229 4202496 623 34742 0 40 0 0 330 18 18 0 1 0 880906444 2658304 299 1283457024 134512640 135304128 4288908320 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17469/statm: 649 299 253 194 0 35 0 [pid=17481] ppid=17469 vsize=109336 CPUtime=21.73 /proc/17481/stat : 17481 (clasp) R 17469 17469 4159 34819 4229 4202496 29541 0 19 0 2159 14 0 0 25 0 1 0 880906448 111960064 26260 1283457024 134512640 136223643 4288716000 18446744073709551615 134704907 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17481/statm: 27334 26260 225 418 0 26914 0 Current children cumulated CPU time (s) 25.21 Current children cumulated vsize (KiB) 111932 [startup+51.1073 s] /proc/loadavg: 1.01 1.03 1.00 2/42 17483 /proc/meminfo: memFree=641012/1048576 swapFree=2080268/2097144 [pid=17469] ppid=17468 vsize=2596 CPUtime=3.48 /proc/17469/stat : 17469 (aspcud-trendy-1) S 17468 17469 4159 34819 4229 4202496 623 34742 0 40 0 0 330 18 18 0 1 0 880906444 2658304 299 1283457024 134512640 135304128 4288908320 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17469/statm: 649 299 253 194 0 35 0 [pid=17481] ppid=17469 vsize=139836 CPUtime=47.31 /proc/17481/stat : 17481 (clasp) R 17469 17469 4159 34819 4229 4202496 37153 0 19 0 4713 18 0 0 25 0 1 0 880906448 143192064 33872 1283457024 134512640 136223643 4288716000 18446744073709551615 134709559 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17481/statm: 34959 33872 225 418 0 34539 0 Current children cumulated CPU time (s) 50.79 Current children cumulated vsize (KiB) 142432 [startup+102.312 s] /proc/loadavg: 1.00 1.03 1.00 2/42 17483 /proc/meminfo: memFree=594016/1048576 swapFree=2080268/2097144 [pid=17469] ppid=17468 vsize=2596 CPUtime=3.48 /proc/17469/stat : 17469 (aspcud-trendy-1) S 17468 17469 4159 34819 4229 4202496 623 34742 0 40 0 0 330 18 18 0 1 0 880906444 2658304 299 1283457024 134512640 135304128 4288908320 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17469/statm: 649 299 253 194 0 35 0 [pid=17481] ppid=17469 vsize=193188 CPUtime=98.45 /proc/17481/stat : 17481 (clasp) R 17469 17469 4159 34819 4229 4202496 50471 0 19 0 9824 21 0 0 25 0 1 0 880906448 197824512 47190 1283457024 134512640 136223643 4288716000 18446744073709551615 135627581 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17481/statm: 48297 47190 225 418 0 47877 0 Current children cumulated CPU time (s) 101.93 Current children cumulated vsize (KiB) 195784 [startup+162.311 s] /proc/loadavg: 1.00 1.02 1.00 2/42 17483 /proc/meminfo: memFree=568472/1048576 swapFree=2080268/2097144 [pid=17469] ppid=17468 vsize=2596 CPUtime=3.48 /proc/17469/stat : 17469 (aspcud-trendy-1) S 17468 17469 4159 34819 4229 4202496 623 34742 0 40 0 0 330 18 18 0 1 0 880906444 2658304 299 1283457024 134512640 135304128 4288908320 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17469/statm: 649 299 253 194 0 35 0 [pid=17481] ppid=17469 vsize=212120 CPUtime=158.38 /proc/17481/stat : 17481 (clasp) R 17469 17469 4159 34819 4229 4202496 55224 0 19 0 15814 24 0 0 25 0 1 0 880906448 217210880 51943 1283457024 134512640 136223643 4288716000 18446744073709551615 134704872 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17481/statm: 53030 51943 225 418 0 52610 0 Current children cumulated CPU time (s) 161.86 Current children cumulated vsize (KiB) 214716 [startup+222.307 s] /proc/loadavg: 1.00 1.01 1.00 2/42 17483 /proc/meminfo: memFree=450796/1048576 swapFree=2080268/2097144 [pid=17469] ppid=17468 vsize=2596 CPUtime=3.48 /proc/17469/stat : 17469 (aspcud-trendy-1) S 17468 17469 4159 34819 4229 4202496 623 34742 0 40 0 0 330 18 18 0 1 0 880906444 2658304 299 1283457024 134512640 135304128 4288908320 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17469/statm: 649 299 253 194 0 35 0 [pid=17481] ppid=17469 vsize=329956 CPUtime=218.33 /proc/17481/stat : 17481 (clasp) R 17469 17469 4159 34819 4229 4202496 84689 0 19 0 21799 34 0 0 25 0 1 0 880906448 337874944 81303 1283457024 134512640 136223643 4288716000 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17481/statm: 82489 81303 225 418 0 82069 0 Current children cumulated CPU time (s) 221.81 Current children cumulated vsize (KiB) 332552 [startup+282.306 s] /proc/loadavg: 1.00 1.01 1.00 2/42 17483 /proc/meminfo: memFree=453028/1048576 swapFree=2080268/2097144 [pid=17469] ppid=17468 vsize=2596 CPUtime=3.48 /proc/17469/stat : 17469 (aspcud-trendy-1) S 17468 17469 4159 34819 4229 4202496 623 34742 0 40 0 0 330 18 18 0 1 0 880906444 2658304 299 1283457024 134512640 135304128 4288908320 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17469/statm: 649 299 253 194 0 35 0 [pid=17481] ppid=17469 vsize=327016 CPUtime=278.28 /proc/17481/stat : 17481 (clasp) R 17469 17469 4159 34819 4229 4202496 84700 0 19 0 27793 35 0 0 25 0 1 0 880906448 334864384 80602 1283457024 134512640 136223643 4288716000 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17481/statm: 81754 80602 225 418 0 81334 0 Current children cumulated CPU time (s) 281.76 Current children cumulated vsize (KiB) 329612 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.608 s] /proc/loadavg: 1.00 1.01 1.00 2/42 17483 /proc/meminfo: memFree=453028/1048576 swapFree=2080268/2097144 [pid=17469] ppid=17468 vsize=2596 CPUtime=3.48 /proc/17469/stat : 17469 (aspcud-trendy-1) S 17468 17469 4159 34819 4229 4202496 623 34742 0 40 0 0 330 18 18 0 1 0 880906444 2658304 299 1283457024 134512640 135304128 4288908320 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17469/statm: 649 299 253 194 0 35 0 [pid=17481] ppid=17469 vsize=327016 CPUtime=286.58 /proc/17481/stat : 17481 (clasp) R 17469 17469 4159 34819 4229 4202496 84701 0 19 0 28623 35 0 0 25 0 1 0 880906448 334864384 80603 1283457024 134512640 136223643 4288716000 18446744073709551615 134664705 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17481/statm: 81754 80603 225 418 0 81334 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 329612 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.667 CPU time (s): 290.106 CPU user time (s): 289.542 CPU system time (s): 0.564035 CPU usage (%): 99.8071 Max. virtual memory (cumulated for all children) (KiB): 332552 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.542 system time used= 0.564035 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 122680 page faults= 60 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 2769 involuntary context switches= 5555 runsolver used 0 second user time and 0.004 second system time The end