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/rand986.sarge-etch-lenny-squeeze.cudf.sarge-etch-lenny-squeeze.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/icse/sarge-etch-lenny-squeeze/rand986.sarge-etch-lenny-squeeze.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand986.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.04 1.08 1.05 1/44 30414 /proc/meminfo: memFree=781208/1048576 swapFree=2077588/2097144 [pid=30414] ppid=30413 vsize=3020 CPUtime=0 /proc/30414/stat : 30414 (runsolver) D 30413 30414 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 25 0 1 0 883962685 3092480 93 1283457024 134512640 134586868 4290223216 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/30414/statm: 755 93 62 19 0 53 0 [startup+0.205222 s] /proc/loadavg: 1.04 1.08 1.05 1/44 30414 /proc/meminfo: memFree=781208/1048576 swapFree=2077588/2097144 [pid=30414] ppid=30413 vsize=2600 CPUtime=0 /proc/30414/stat : 30414 (aspcud-trendy-1) S 30413 30414 4159 34819 4229 4202496 624 2213 0 3 0 0 0 0 25 0 1 0 883962685 2662400 300 1283457024 134512640 135304128 4292888544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30414/statm: 650 300 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.308161 s] /proc/loadavg: 1.04 1.08 1.05 1/44 30414 /proc/meminfo: memFree=781208/1048576 swapFree=2077588/2097144 [pid=30414] ppid=30413 vsize=2600 CPUtime=0 /proc/30414/stat : 30414 (aspcud-trendy-1) S 30413 30414 4159 34819 4229 4202496 624 2213 0 3 0 0 0 0 25 0 1 0 883962685 2662400 300 1283457024 134512640 135304128 4292888544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30414/statm: 650 300 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.40819 s] /proc/loadavg: 1.04 1.08 1.05 1/44 30414 /proc/meminfo: memFree=781208/1048576 swapFree=2077588/2097144 [pid=30414] ppid=30413 vsize=2600 CPUtime=0 /proc/30414/stat : 30414 (aspcud-trendy-1) S 30413 30414 4159 34819 4229 4202496 624 2213 0 3 0 0 0 0 25 0 1 0 883962685 2662400 300 1283457024 134512640 135304128 4292888544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30414/statm: 650 300 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.708282 s] /proc/loadavg: 1.04 1.08 1.05 1/44 30414 /proc/meminfo: memFree=781208/1048576 swapFree=2077588/2097144 [pid=30414] ppid=30413 vsize=2600 CPUtime=0 /proc/30414/stat : 30414 (aspcud-trendy-1) S 30413 30414 4159 34819 4229 4202496 624 2213 0 3 0 0 0 0 25 0 1 0 883962685 2662400 300 1283457024 134512640 135304128 4292888544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30414/statm: 650 300 253 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+1.50849 s] /proc/loadavg: 1.03 1.07 1.05 2/48 30428 /proc/meminfo: memFree=736316/1048576 swapFree=2077588/2097144 [pid=30414] ppid=30413 vsize=2600 CPUtime=0 /proc/30414/stat : 30414 (aspcud-trendy-1) S 30413 30414 4159 34819 4229 4202496 624 2213 0 3 0 0 0 0 25 0 1 0 883962685 2662400 300 1283457024 134512640 135304128 4292888544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30414/statm: 650 300 253 194 0 36 0 [pid=30426] ppid=30414 vsize=3572 CPUtime=0 /proc/30426/stat : 30426 (clasp) S 30414 30414 4159 34819 4229 4202496 739 0 18 0 0 0 0 0 18 0 1 0 883962689 3657728 625 1283457024 134512640 136223643 4290262384 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/30426/statm: 893 625 174 418 0 473 0 [pid=30427] ppid=30414 vsize=5024 CPUtime=0.12 /proc/30427/stat : 30427 (gringo) R 30414 30414 4159 34819 4229 4202496 1045 0 22 0 12 0 0 0 18 0 1 0 883962689 5144576 789 1283457024 134512640 136959103 4293583120 18446744073709551615 136227621 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30427/statm: 1256 789 247 598 0 655 0 [pid=30428] ppid=30414 vsize=43452 CPUtime=1.21 /proc/30428/stat : 30428 (cudf2lp) R 30414 30414 4159 34819 4229 4202496 14008 0 14 0 119 2 0 0 25 0 1 0 883962690 44494848 10657 1283457024 134512640 135749571 4287768192 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0 /proc/30428/statm: 10863 10657 129 302 0 10559 0 Current children cumulated CPU time (s) 1.33 Current children cumulated vsize (KiB) 54648 [startup+3.10888 s] /proc/loadavg: 1.03 1.07 1.05 3/48 30428 /proc/meminfo: memFree=705076/1048576 swapFree=2077588/2097144 [pid=30414] ppid=30413 vsize=2600 CPUtime=1.49 /proc/30414/stat : 30414 (aspcud-trendy-1) S 30413 30414 4159 34819 4229 4202496 625 16224 0 18 0 0 144 5 18 0 1 0 883962685 2662400 300 1283457024 134512640 135304128 4292888544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30414/statm: 650 300 253 194 0 36 0 [pid=30426] ppid=30414 vsize=31888 CPUtime=0.2 /proc/30426/stat : 30426 (clasp) R 30414 30414 4159 34819 4229 4202496 8997 0 18 0 16 4 0 0 18 0 1 0 883962689 32653312 7515 1283457024 134512640 136223643 4290262384 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30426/statm: 7972 7515 174 418 0 7552 0 [pid=30427] ppid=30414 vsize=48716 CPUtime=1.23 /proc/30427/stat : 30427 (gringo) R 30414 30414 4159 34819 4229 4202496 14170 0 22 0 117 6 0 0 18 0 1 0 883962689 49885184 9866 1283457024 134512640 136959103 4293583120 18446744073709551615 136227613 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30427/statm: 12179 9866 256 598 0 11578 0 Current children cumulated CPU time (s) 2.92 Current children cumulated vsize (KiB) 83204 [startup+6.31023 s] /proc/loadavg: 1.03 1.07 1.05 2/46 30428 /proc/meminfo: memFree=724640/1048576 swapFree=2077588/2097144 [pid=30414] ppid=30413 vsize=2600 CPUtime=3.36 /proc/30414/stat : 30414 (aspcud-trendy-1) S 30413 30414 4159 34819 4229 4202496 625 34746 0 40 0 0 318 18 18 0 1 0 883962685 2662400 300 1283457024 134512640 135304128 4292888544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30414/statm: 650 300 253 194 0 36 0 [pid=30426] ppid=30414 vsize=55916 CPUtime=2.74 /proc/30426/stat : 30426 (clasp) R 30414 30414 4159 34819 4229 4202496 16189 0 19 0 270 4 0 0 22 0 1 0 883962689 57257984 12907 1283457024 134512640 136223643 4290262384 18446744073709551615 134711263 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30426/statm: 13979 12907 225 418 0 13559 0 Current children cumulated CPU time (s) 6.1 Current children cumulated vsize (KiB) 58516 [startup+12.712 s] /proc/loadavg: 1.03 1.07 1.05 2/46 30428 /proc/meminfo: memFree=704552/1048576 swapFree=2077588/2097144 [pid=30414] ppid=30413 vsize=2600 CPUtime=3.36 /proc/30414/stat : 30414 (aspcud-trendy-1) S 30413 30414 4159 34819 4229 4202496 625 34746 0 40 0 0 318 18 18 0 1 0 883962685 2662400 300 1283457024 134512640 135304128 4292888544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30414/statm: 650 300 253 194 0 36 0 [pid=30426] ppid=30414 vsize=80332 CPUtime=9.15 /proc/30426/stat : 30426 (clasp) R 30414 30414 4159 34819 4229 4202496 22297 0 19 0 907 8 0 0 25 0 1 0 883962689 82259968 19015 1283457024 134512640 136223643 4290262384 18446744073709551615 134929384 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30426/statm: 20083 19015 225 418 0 19663 0 Current children cumulated CPU time (s) 12.51 Current children cumulated vsize (KiB) 82932 [startup+25.5054 s] /proc/loadavg: 1.02 1.07 1.05 2/46 30428 /proc/meminfo: memFree=687812/1048576 swapFree=2077588/2097144 [pid=30414] ppid=30413 vsize=2600 CPUtime=3.36 /proc/30414/stat : 30414 (aspcud-trendy-1) S 30413 30414 4159 34819 4229 4202496 625 34746 0 40 0 0 318 18 18 0 1 0 883962685 2662400 300 1283457024 134512640 135304128 4292888544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30414/statm: 650 300 253 194 0 36 0 [pid=30426] ppid=30414 vsize=93928 CPUtime=21.92 /proc/30426/stat : 30426 (clasp) R 30414 30414 4159 34819 4229 4202496 25706 0 19 0 2183 9 0 0 25 0 1 0 883962689 96182272 22424 1283457024 134512640 136223643 4290262384 18446744073709551615 134704872 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30426/statm: 23482 22424 225 418 0 23062 0 Current children cumulated CPU time (s) 25.28 Current children cumulated vsize (KiB) 96528 [startup+51.1022 s] /proc/loadavg: 1.01 1.06 1.04 2/46 30428 /proc/meminfo: memFree=667848/1048576 swapFree=2077588/2097144 [pid=30414] ppid=30413 vsize=2600 CPUtime=3.36 /proc/30414/stat : 30414 (aspcud-trendy-1) S 30413 30414 4159 34819 4229 4202496 625 34746 0 40 0 0 318 18 18 0 1 0 883962685 2662400 300 1283457024 134512640 135304128 4292888544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30414/statm: 650 300 253 194 0 36 0 [pid=30426] ppid=30414 vsize=112528 CPUtime=47.52 /proc/30426/stat : 30426 (clasp) R 30414 30414 4159 34819 4229 4202496 30901 0 19 0 4739 13 0 0 25 0 1 0 883962689 115228672 27074 1283457024 134512640 136223643 4290262384 18446744073709551615 134650568 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30426/statm: 28132 27074 225 418 0 27712 0 Current children cumulated CPU time (s) 50.88 Current children cumulated vsize (KiB) 115128 [startup+102.304 s] /proc/loadavg: 1.00 1.05 1.04 2/46 30428 /proc/meminfo: memFree=602252/1048576 swapFree=2077588/2097144 [pid=30414] ppid=30413 vsize=2600 CPUtime=3.36 /proc/30414/stat : 30414 (aspcud-trendy-1) S 30413 30414 4159 34819 4229 4202496 625 34746 0 40 0 0 318 18 18 0 1 0 883962685 2662400 300 1283457024 134512640 135304128 4292888544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30414/statm: 650 300 253 194 0 36 0 [pid=30426] ppid=30414 vsize=178368 CPUtime=98.67 /proc/30426/stat : 30426 (clasp) R 30414 30414 4159 34819 4229 4202496 47338 0 19 0 9851 16 0 0 25 0 1 0 883962689 182648832 43511 1283457024 134512640 136223643 4290262384 18446744073709551615 134650252 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30426/statm: 44592 43511 225 418 0 44172 0 Current children cumulated CPU time (s) 102.03 Current children cumulated vsize (KiB) 180968 [startup+162.31 s] /proc/loadavg: 1.00 1.04 1.03 2/46 30428 /proc/meminfo: memFree=556868/1048576 swapFree=2077588/2097144 [pid=30414] ppid=30413 vsize=2600 CPUtime=3.36 /proc/30414/stat : 30414 (aspcud-trendy-1) S 30413 30414 4159 34819 4229 4202496 625 34746 0 40 0 0 318 18 18 0 1 0 883962685 2662400 300 1283457024 134512640 135304128 4292888544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30414/statm: 650 300 253 194 0 36 0 [pid=30426] ppid=30414 vsize=223076 CPUtime=158.64 /proc/30426/stat : 30426 (clasp) R 30414 30414 4159 34819 4229 4202496 60118 0 19 0 15840 24 0 0 25 0 1 0 883962689 228429824 54686 1283457024 134512640 136223643 4290262384 18446744073709551615 134928897 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30426/statm: 55769 54686 225 418 0 55349 0 Current children cumulated CPU time (s) 162 Current children cumulated vsize (KiB) 225676 [startup+222.307 s] /proc/loadavg: 1.00 1.03 1.03 2/46 30428 /proc/meminfo: memFree=549056/1048576 swapFree=2077588/2097144 [pid=30414] ppid=30413 vsize=2600 CPUtime=3.36 /proc/30414/stat : 30414 (aspcud-trendy-1) S 30413 30414 4159 34819 4229 4202496 625 34746 0 40 0 0 318 18 18 0 1 0 883962685 2662400 300 1283457024 134512640 135304128 4292888544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30414/statm: 650 300 253 194 0 36 0 [pid=30426] ppid=30414 vsize=230756 CPUtime=218.58 /proc/30426/stat : 30426 (clasp) R 30414 30414 4159 34819 4229 4202496 62317 0 19 0 21831 27 0 0 25 0 1 0 883962689 236294144 56608 1283457024 134512640 136223643 4290262384 18446744073709551615 134940730 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30426/statm: 57689 56608 225 418 0 57269 0 Current children cumulated CPU time (s) 221.94 Current children cumulated vsize (KiB) 233356 [startup+282.306 s] /proc/loadavg: 1.00 1.02 1.02 2/46 30428 /proc/meminfo: memFree=513840/1048576 swapFree=2077588/2097144 [pid=30414] ppid=30413 vsize=2600 CPUtime=3.36 /proc/30414/stat : 30414 (aspcud-trendy-1) S 30413 30414 4159 34819 4229 4202496 625 34746 0 40 0 0 318 18 18 0 1 0 883962685 2662400 300 1283457024 134512640 135304128 4292888544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30414/statm: 650 300 253 194 0 36 0 [pid=30426] ppid=30414 vsize=265812 CPUtime=278.55 /proc/30426/stat : 30426 (clasp) R 30414 30414 4159 34819 4229 4202496 79062 0 19 0 27822 33 0 0 25 0 1 0 883962689 272191488 65371 1283457024 134512640 136223643 4290262384 18446744073709551615 134929396 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30426/statm: 66453 65371 225 418 0 66033 0 Current children cumulated CPU time (s) 281.91 Current children cumulated vsize (KiB) 268412 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.409 s] /proc/loadavg: 1.00 1.02 1.02 2/46 30428 /proc/meminfo: memFree=513840/1048576 swapFree=2077588/2097144 [pid=30414] ppid=30413 vsize=2600 CPUtime=3.36 /proc/30414/stat : 30414 (aspcud-trendy-1) S 30413 30414 4159 34819 4229 4202496 625 34746 0 40 0 0 318 18 18 0 1 0 883962685 2662400 300 1283457024 134512640 135304128 4292888544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30414/statm: 650 300 253 194 0 36 0 [pid=30426] ppid=30414 vsize=265812 CPUtime=286.65 /proc/30426/stat : 30426 (clasp) R 30414 30414 4159 34819 4229 4202496 79062 0 19 0 28632 33 0 0 25 0 1 0 883962689 272191488 65371 1283457024 134512640 136223643 4290262384 18446744073709551615 134712067 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30426/statm: 66453 65371 225 418 0 66033 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 268412 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.464 CPU time (s): 290.058 CPU user time (s): 289.518 CPU system time (s): 0.540033 CPU usage (%): 99.8604 Max. virtual memory (cumulated for all children) (KiB): 300452 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.518 system time used= 0.540033 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 117055 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= 2741 involuntary context switches= 5739 runsolver used 0 second user time and 0 second system time The end