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/rand316.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/icse/sarge-etch-lenny-squeeze-sid/rand316.sarge-etch-lenny-squeeze-sid.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand316.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: 1.07 1.05 1.01 2/40 14645 /proc/meminfo: memFree=769388/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=3024 CPUtime=0 /proc/14645/stat : 14645 (runsolver) D 14644 14645 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 25 0 1 0 880095640 3096576 94 1283457024 134512640 134586868 4290729168 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/14645/statm: 756 94 62 19 0 54 0 [startup+0.107396 s] /proc/loadavg: 1.07 1.05 1.01 2/40 14645 /proc/meminfo: memFree=769388/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=2604 CPUtime=0 /proc/14645/stat : 14645 (aspcud-trendy-1) S 14644 14645 4159 34819 4229 4202496 622 2213 3 3 0 0 0 0 25 0 1 0 880095640 2666496 301 1283457024 134512640 135304128 4286890528 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14645/statm: 651 301 253 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2604 [startup+0.207315 s] /proc/loadavg: 1.07 1.05 1.01 2/40 14645 /proc/meminfo: memFree=769388/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=2604 CPUtime=0 /proc/14645/stat : 14645 (aspcud-trendy-1) S 14644 14645 4159 34819 4229 4202496 622 2213 3 3 0 0 0 0 25 0 1 0 880095640 2666496 301 1283457024 134512640 135304128 4286890528 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14645/statm: 651 301 253 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2604 [startup+0.307304 s] /proc/loadavg: 1.07 1.05 1.01 2/40 14645 /proc/meminfo: memFree=769388/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=2604 CPUtime=0 /proc/14645/stat : 14645 (aspcud-trendy-1) S 14644 14645 4159 34819 4229 4202496 622 2213 3 3 0 0 0 0 25 0 1 0 880095640 2666496 301 1283457024 134512640 135304128 4286890528 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14645/statm: 651 301 253 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2604 [startup+0.71241 s] /proc/loadavg: 1.07 1.05 1.01 2/40 14645 /proc/meminfo: memFree=769388/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=2604 CPUtime=0 /proc/14645/stat : 14645 (aspcud-trendy-1) S 14644 14645 4159 34819 4229 4202496 622 2213 3 3 0 0 0 0 25 0 1 0 880095640 2666496 301 1283457024 134512640 135304128 4286890528 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14645/statm: 651 301 253 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2604 [startup+1.51289 s] /proc/loadavg: 1.07 1.05 1.01 2/44 14659 /proc/meminfo: memFree=731884/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=2604 CPUtime=0 /proc/14645/stat : 14645 (aspcud-trendy-1) S 14644 14645 4159 34819 4229 4202496 622 2213 3 3 0 0 0 0 25 0 1 0 880095640 2666496 301 1283457024 134512640 135304128 4286890528 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14645/statm: 651 301 253 194 0 37 0 [pid=14657] ppid=14645 vsize=1872 CPUtime=0 /proc/14657/stat : 14657 (clasp) S 14645 14645 4159 34819 4229 4202496 270 0 15 0 0 0 0 0 23 0 1 0 880095645 1916928 153 1283457024 134512640 136223643 4289140592 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/14657/statm: 468 153 138 418 0 48 0 [pid=14658] ppid=14645 vsize=2612 CPUtime=0 /proc/14658/stat : 14658 (gringo) S 14645 14645 4159 34819 4229 4202496 386 0 22 0 0 0 0 0 23 0 1 0 880095645 2674688 277 1283457024 134512640 136959103 4289139888 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/14658/statm: 653 277 247 598 0 52 0 [pid=14659] ppid=14645 vsize=53196 CPUtime=1.21 /proc/14659/stat : 14659 (cudf2lp) R 14645 14645 4159 34819 4229 4202496 14438 0 14 0 118 3 0 0 25 0 1 0 880095645 54472704 12299 1283457024 134512640 135749571 4289145248 18446744073709551615 135179689 0 0 6 0 0 0 0 17 0 0 0 0 /proc/14659/statm: 13299 12299 127 302 0 12995 0 Current children cumulated CPU time (s) 1.21 Current children cumulated vsize (KiB) 60284 [startup+3.1134 s] /proc/loadavg: 1.07 1.05 1.01 3/44 14659 /proc/meminfo: memFree=699960/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=2604 CPUtime=1.69 /proc/14645/stat : 14645 (aspcud-trendy-1) S 14644 14645 4159 34819 4229 4202496 623 16758 3 18 0 0 162 7 18 0 1 0 880095640 2666496 301 1283457024 134512640 135304128 4286890528 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14645/statm: 651 301 253 194 0 37 0 [pid=14657] ppid=14645 vsize=24684 CPUtime=0.07 /proc/14657/stat : 14657 (clasp) R 14645 14645 4159 34819 4229 4202496 6966 0 18 0 5 2 0 0 18 0 1 0 880095645 25276416 5788 1283457024 134512640 136223643 4289140592 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14657/statm: 6171 5788 174 418 0 5751 0 [pid=14658] ppid=14645 vsize=38224 CPUtime=1.03 /proc/14658/stat : 14658 (gringo) R 14645 14645 4159 34819 4229 4202496 11604 0 22 0 100 3 0 0 18 0 1 0 880095645 39141376 7686 1283457024 134512640 136959103 4289139888 18446744073709551615 134823978 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14658/statm: 9556 7686 256 598 0 8955 0 Current children cumulated CPU time (s) 2.79 Current children cumulated vsize (KiB) 65512 [startup+6.30442 s] /proc/loadavg: 1.06 1.05 1.00 2/42 14659 /proc/meminfo: memFree=708924/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=2604 CPUtime=3.68 /proc/14645/stat : 14645 (aspcud-trendy-1) S 14644 14645 4159 34819 4229 4202496 623 36118 3 40 0 0 352 16 18 0 1 0 880095640 2666496 301 1283457024 134512640 135304128 4286890528 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14645/statm: 651 301 253 194 0 37 0 [pid=14657] ppid=14645 vsize=59228 CPUtime=2.31 /proc/14657/stat : 14657 (clasp) R 14645 14645 4159 34819 4229 4202496 17366 0 19 0 226 5 0 0 20 0 1 0 880095645 60649472 13681 1283457024 134512640 136223643 4289140592 18446744073709551615 134650459 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14657/statm: 14807 13681 223 418 0 14387 0 Current children cumulated CPU time (s) 5.99 Current children cumulated vsize (KiB) 61832 [startup+12.7064 s] /proc/loadavg: 1.06 1.04 1.00 2/42 14659 /proc/meminfo: memFree=709684/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=2604 CPUtime=3.68 /proc/14645/stat : 14645 (aspcud-trendy-1) S 14644 14645 4159 34819 4229 4202496 623 36118 3 40 0 0 352 16 18 0 1 0 880095640 2666496 301 1283457024 134512640 135304128 4286890528 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14645/statm: 651 301 253 194 0 37 0 [pid=14657] ppid=14645 vsize=64508 CPUtime=8.7 /proc/14657/stat : 14657 (clasp) R 14645 14645 4159 34819 4229 4202496 18689 0 19 0 864 6 0 0 25 0 1 0 880095645 66056192 15004 1283457024 134512640 136223643 4289140592 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14657/statm: 16127 15004 225 418 0 15707 0 Current children cumulated CPU time (s) 12.38 Current children cumulated vsize (KiB) 67112 [startup+25.5096 s] /proc/loadavg: 1.04 1.04 1.00 2/42 14659 /proc/meminfo: memFree=668888/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=2604 CPUtime=3.68 /proc/14645/stat : 14645 (aspcud-trendy-1) S 14644 14645 4159 34819 4229 4202496 623 36118 3 40 0 0 352 16 18 0 1 0 880095640 2666496 301 1283457024 134512640 135304128 4286890528 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14645/statm: 651 301 253 194 0 37 0 [pid=14657] ppid=14645 vsize=100360 CPUtime=21.51 /proc/14657/stat : 14657 (clasp) R 14645 14645 4159 34819 4229 4202496 27660 0 19 0 2143 8 0 0 25 0 1 0 880095645 102768640 23975 1283457024 134512640 136223643 4289140592 18446744073709551615 134711275 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14657/statm: 25090 23975 225 418 0 24670 0 Current children cumulated CPU time (s) 25.19 Current children cumulated vsize (KiB) 102964 [startup+51.1062 s] /proc/loadavg: 1.03 1.04 1.00 2/42 14659 /proc/meminfo: memFree=598580/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=2604 CPUtime=3.68 /proc/14645/stat : 14645 (aspcud-trendy-1) S 14644 14645 4159 34819 4229 4202496 623 36118 3 40 0 0 352 16 18 0 1 0 880095640 2666496 301 1283457024 134512640 135304128 4286890528 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14645/statm: 651 301 253 194 0 37 0 [pid=14657] ppid=14645 vsize=175832 CPUtime=47.09 /proc/14657/stat : 14657 (clasp) R 14645 14645 4159 34819 4229 4202496 46501 0 19 0 4691 18 0 0 25 0 1 0 880095645 180051968 42816 1283457024 134512640 136223643 4289140592 18446744073709551615 134922726 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14657/statm: 43958 42816 225 418 0 43538 0 Current children cumulated CPU time (s) 50.77 Current children cumulated vsize (KiB) 178436 [startup+102.309 s] /proc/loadavg: 1.01 1.03 1.00 2/42 14659 /proc/meminfo: memFree=534596/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=2604 CPUtime=3.68 /proc/14645/stat : 14645 (aspcud-trendy-1) S 14644 14645 4159 34819 4229 4202496 623 36118 3 40 0 0 352 16 18 0 1 0 880095640 2666496 301 1283457024 134512640 135304128 4286890528 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14645/statm: 651 301 253 194 0 37 0 [pid=14657] ppid=14645 vsize=234388 CPUtime=98.25 /proc/14657/stat : 14657 (clasp) R 14645 14645 4159 34819 4229 4202496 61151 0 19 0 9797 28 0 0 25 0 1 0 880095645 240013312 57466 1283457024 134512640 136223643 4289140592 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14657/statm: 58597 57466 225 418 0 58177 0 Current children cumulated CPU time (s) 101.93 Current children cumulated vsize (KiB) 236992 [startup+162.309 s] /proc/loadavg: 1.00 1.02 1.00 2/42 14659 /proc/meminfo: memFree=496776/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=2604 CPUtime=3.68 /proc/14645/stat : 14645 (aspcud-trendy-1) S 14644 14645 4159 34819 4229 4202496 623 36118 3 40 0 0 352 16 18 0 1 0 880095640 2666496 301 1283457024 134512640 135304128 4286890528 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14645/statm: 651 301 253 194 0 37 0 [pid=14657] ppid=14645 vsize=272408 CPUtime=158.17 /proc/14657/stat : 14657 (clasp) R 14645 14645 4159 34819 4229 4202496 70592 0 19 0 15783 34 0 0 25 0 1 0 880095645 278945792 66907 1283457024 134512640 136223643 4289140592 18446744073709551615 134924387 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14657/statm: 68102 66907 225 418 0 67682 0 Current children cumulated CPU time (s) 161.85 Current children cumulated vsize (KiB) 275012 [startup+222.31 s] /proc/loadavg: 1.00 1.02 1.00 2/42 14659 /proc/meminfo: memFree=455484/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=2604 CPUtime=3.68 /proc/14645/stat : 14645 (aspcud-trendy-1) S 14644 14645 4159 34819 4229 4202496 623 36118 3 40 0 0 352 16 18 0 1 0 880095640 2666496 301 1283457024 134512640 135304128 4286890528 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14645/statm: 651 301 253 194 0 37 0 [pid=14657] ppid=14645 vsize=313132 CPUtime=218.1 /proc/14657/stat : 14657 (clasp) R 14645 14645 4159 34819 4229 4202496 81132 0 19 0 21770 40 0 0 25 0 1 0 880095645 320647168 77062 1283457024 134512640 136223643 4289140592 18446744073709551615 134711220 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14657/statm: 78283 77062 225 418 0 77863 0 Current children cumulated CPU time (s) 221.78 Current children cumulated vsize (KiB) 315736 [startup+282.308 s] /proc/loadavg: 1.00 1.01 1.00 2/42 14659 /proc/meminfo: memFree=401916/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=2604 CPUtime=3.68 /proc/14645/stat : 14645 (aspcud-trendy-1) S 14644 14645 4159 34819 4229 4202496 623 36118 3 40 0 0 352 16 18 0 1 0 880095640 2666496 301 1283457024 134512640 135304128 4286890528 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14645/statm: 651 301 253 194 0 37 0 [pid=14657] ppid=14645 vsize=367300 CPUtime=278.04 /proc/14657/stat : 14657 (clasp) R 14645 14645 4159 34819 4229 4202496 94634 0 19 0 27758 46 0 0 25 0 1 0 880095645 376115200 90564 1283457024 134512640 136223643 4289140592 18446744073709551615 134931129 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14657/statm: 91825 90564 225 418 0 91405 0 Current children cumulated CPU time (s) 281.72 Current children cumulated vsize (KiB) 369904 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.611 s] /proc/loadavg: 1.00 1.01 1.00 2/42 14659 /proc/meminfo: memFree=388524/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=2604 CPUtime=3.68 /proc/14645/stat : 14645 (aspcud-trendy-1) S 14644 14645 4159 34819 4229 4202496 623 36118 3 40 0 0 352 16 18 0 1 0 880095640 2666496 301 1283457024 134512640 135304128 4286890528 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14645/statm: 651 301 253 194 0 37 0 [pid=14657] ppid=14645 vsize=380652 CPUtime=286.34 /proc/14657/stat : 14657 (clasp) R 14645 14645 4159 34819 4229 4202496 97985 0 19 0 28588 46 0 0 25 0 1 0 880095645 389787648 93915 1283457024 134512640 136223643 4289140592 18446744073709551615 134931096 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14657/statm: 95163 93915 225 418 0 94743 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 383256 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.611 s] /proc/loadavg: 1.00 1.01 1.00 2/42 14659 /proc/meminfo: memFree=388524/1048576 swapFree=2080252/2097144 [pid=14645] ppid=14644 vsize=2604 CPUtime=3.68 /proc/14645/stat : 14645 (aspcud-trendy-1) S 14644 14645 4159 34819 4229 4202496 623 36118 3 40 0 0 352 16 18 0 1 0 880095640 2666496 301 1283457024 134512640 135304128 4286890528 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/14645/statm: 651 301 253 194 0 37 0 [pid=14657] ppid=14645 vsize=380652 CPUtime=286.34 /proc/14657/stat : 14657 (clasp) R 14645 14645 4159 34819 4229 4202496 97985 0 19 0 28588 46 0 0 25 0 1 0 880095645 389787648 93915 1283457024 134512640 136223643 4289140592 18446744073709551615 134931096 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/14657/statm: 95163 93915 225 418 0 94743 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 383256 Child status: 0 Real time (s): 290.679 CPU time (s): 290.062 CPU user time (s): 289.41 CPU system time (s): 0.65204 CPU usage (%): 99.7878 Max. virtual memory (cumulated for all children) (KiB): 383256 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.41 system time used= 0.65204 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 137334 page faults= 64 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 3125 involuntary context switches= 5892 runsolver used 0.004 second user time and 0 second system time The end