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-sid.cudf.sarge-etch-lenny-squeeze-sid.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/icse/sarge-etch-lenny-squeeze-sid/rand986.sarge-etch-lenny-squeeze-sid.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand986.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.19 1.17 1.10 1/44 30149 /proc/meminfo: memFree=771596/1048576 swapFree=2077608/2097144 [pid=30149] ppid=30148 vsize=3028 CPUtime=0 /proc/30149/stat : 30149 (runsolver) D 30148 30149 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 25 0 1 0 883839664 3100672 94 1283457024 134512640 134586868 4290942208 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/30149/statm: 757 94 62 19 0 55 0 [startup+0.113535 s] /proc/loadavg: 1.19 1.17 1.10 1/44 30149 /proc/meminfo: memFree=771596/1048576 swapFree=2077608/2097144 [pid=30149] ppid=30148 vsize=2604 CPUtime=0 /proc/30149/stat : 30149 (aspcud-trendy-1) S 30148 30149 4159 34819 4229 4202496 625 2211 0 3 0 0 0 0 25 0 1 0 883839664 2666496 301 1283457024 134512640 135304128 4287386256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30149/statm: 651 301 253 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2604 [startup+0.205517 s] /proc/loadavg: 1.19 1.17 1.10 1/44 30149 /proc/meminfo: memFree=771596/1048576 swapFree=2077608/2097144 [pid=30149] ppid=30148 vsize=2604 CPUtime=0 /proc/30149/stat : 30149 (aspcud-trendy-1) S 30148 30149 4159 34819 4229 4202496 625 2211 0 3 0 0 0 0 25 0 1 0 883839664 2666496 301 1283457024 134512640 135304128 4287386256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30149/statm: 651 301 253 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2604 [startup+0.313683 s] /proc/loadavg: 1.19 1.17 1.10 1/44 30149 /proc/meminfo: memFree=771596/1048576 swapFree=2077608/2097144 [pid=30149] ppid=30148 vsize=2604 CPUtime=0 /proc/30149/stat : 30149 (aspcud-trendy-1) S 30148 30149 4159 34819 4229 4202496 625 2211 0 3 0 0 0 0 25 0 1 0 883839664 2666496 301 1283457024 134512640 135304128 4287386256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30149/statm: 651 301 253 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2604 [startup+0.713765 s] /proc/loadavg: 1.19 1.17 1.10 1/44 30149 /proc/meminfo: memFree=771596/1048576 swapFree=2077608/2097144 [pid=30149] ppid=30148 vsize=2604 CPUtime=0 /proc/30149/stat : 30149 (aspcud-trendy-1) S 30148 30149 4159 34819 4229 4202496 625 2211 0 3 0 0 0 0 25 0 1 0 883839664 2666496 301 1283457024 134512640 135304128 4287386256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30149/statm: 651 301 253 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2604 [startup+1.51396 s] /proc/loadavg: 1.17 1.17 1.09 2/48 30163 /proc/meminfo: memFree=733904/1048576 swapFree=2077608/2097144 [pid=30149] ppid=30148 vsize=2604 CPUtime=0 /proc/30149/stat : 30149 (aspcud-trendy-1) S 30148 30149 4159 34819 4229 4202496 625 2211 0 3 0 0 0 0 25 0 1 0 883839664 2666496 301 1283457024 134512640 135304128 4287386256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30149/statm: 651 301 253 194 0 37 0 [pid=30161] ppid=30149 vsize=1864 CPUtime=0 /proc/30161/stat : 30161 (clasp) S 30149 30149 4159 34819 4229 4202496 268 0 16 0 0 0 0 0 24 0 1 0 883839669 1908736 152 1283457024 134512640 136223643 4289605568 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/30161/statm: 466 152 138 418 0 46 0 [pid=30162] ppid=30149 vsize=2612 CPUtime=0 /proc/30162/stat : 30162 (gringo) S 30149 30149 4159 34819 4229 4202496 386 0 22 0 0 0 0 0 23 0 1 0 883839669 2674688 277 1283457024 134512640 136959103 4288022544 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/30162/statm: 653 277 247 598 0 52 0 [pid=30163] ppid=30149 vsize=45400 CPUtime=1.27 /proc/30163/stat : 30163 (cudf2lp) R 30149 30149 4159 34819 4229 4202496 14539 0 14 0 123 4 0 0 25 0 1 0 883839669 46489600 11142 1283457024 134512640 135749571 4289183360 18446744073709551615 134546118 0 0 6 0 0 0 0 17 0 0 0 0 /proc/30163/statm: 11350 11142 127 302 0 11046 0 Current children cumulated CPU time (s) 1.27 Current children cumulated vsize (KiB) 52480 [startup+3.10774 s] /proc/loadavg: 1.17 1.17 1.09 4/48 30163 /proc/meminfo: memFree=700556/1048576 swapFree=2077608/2097144 [pid=30149] ppid=30148 vsize=2604 CPUtime=1.6 /proc/30149/stat : 30149 (aspcud-trendy-1) S 30148 30149 4159 34819 4229 4202496 626 16756 0 18 0 0 155 5 18 0 1 0 883839664 2666496 301 1283457024 134512640 135304128 4287386256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30149/statm: 651 301 253 194 0 37 0 [pid=30161] ppid=30149 vsize=25864 CPUtime=0.11 /proc/30161/stat : 30161 (clasp) R 30149 30149 4159 34819 4229 4202496 7258 0 19 0 10 1 0 0 18 0 1 0 883839669 26484736 6081 1283457024 134512640 136223643 4289605568 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30161/statm: 6466 6081 174 418 0 6046 0 [pid=30162] ppid=30149 vsize=41420 CPUtime=1.13 /proc/30162/stat : 30162 (gringo) R 30149 30149 4159 34819 4229 4202496 12700 0 22 0 112 1 0 0 18 0 1 0 883839669 42414080 8396 1283457024 134512640 136959103 4288022544 18446744073709551615 134696593 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30162/statm: 10355 8396 256 598 0 9754 0 Current children cumulated CPU time (s) 2.84 Current children cumulated vsize (KiB) 69888 [startup+6.30864 s] /proc/loadavg: 1.17 1.17 1.09 2/46 30163 /proc/meminfo: memFree=712432/1048576 swapFree=2077608/2097144 [pid=30149] ppid=30148 vsize=2604 CPUtime=3.59 /proc/30149/stat : 30149 (aspcud-trendy-1) S 30148 30149 4159 34819 4229 4202496 626 35979 0 40 0 0 346 13 18 0 1 0 883839664 2666496 301 1283457024 134512640 135304128 4287386256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30149/statm: 651 301 253 194 0 37 0 [pid=30161] ppid=30149 vsize=58692 CPUtime=2.44 /proc/30161/stat : 30161 (clasp) R 30149 30149 4159 34819 4229 4202496 17452 0 20 0 238 6 0 0 21 0 1 0 883839669 60100608 13569 1283457024 134512640 136223643 4289605568 18446744073709551615 134931442 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30161/statm: 14673 13569 225 418 0 14253 0 Current children cumulated CPU time (s) 6.03 Current children cumulated vsize (KiB) 61296 [startup+12.7103 s] /proc/loadavg: 1.15 1.16 1.09 2/46 30163 /proc/meminfo: memFree=701148/1048576 swapFree=2077608/2097144 [pid=30149] ppid=30148 vsize=2604 CPUtime=3.59 /proc/30149/stat : 30149 (aspcud-trendy-1) S 30148 30149 4159 34819 4229 4202496 626 35979 0 40 0 0 346 13 18 0 1 0 883839664 2666496 301 1283457024 134512640 135304128 4287386256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30149/statm: 651 301 253 194 0 37 0 [pid=30161] ppid=30149 vsize=72036 CPUtime=8.83 /proc/30161/stat : 30161 (clasp) R 30149 30149 4159 34819 4229 4202496 21261 0 20 0 875 8 0 0 25 0 1 0 883839669 73764864 16918 1283457024 134512640 136223643 4289605568 18446744073709551615 134598493 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30161/statm: 18009 16918 225 418 0 17589 0 Current children cumulated CPU time (s) 12.42 Current children cumulated vsize (KiB) 74640 [startup+25.5132 s] /proc/loadavg: 1.12 1.16 1.09 2/46 30163 /proc/meminfo: memFree=670644/1048576 swapFree=2077608/2097144 [pid=30149] ppid=30148 vsize=2604 CPUtime=3.59 /proc/30149/stat : 30149 (aspcud-trendy-1) S 30148 30149 4159 34819 4229 4202496 626 35979 0 40 0 0 346 13 18 0 1 0 883839664 2666496 301 1283457024 134512640 135304128 4287386256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30149/statm: 651 301 253 194 0 37 0 [pid=30161] ppid=30149 vsize=100180 CPUtime=21.63 /proc/30161/stat : 30161 (clasp) R 30149 30149 4159 34819 4229 4202496 29168 0 20 0 2152 11 0 0 25 0 1 0 883839669 102584320 23956 1283457024 134512640 136223643 4289605568 18446744073709551615 134704872 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30161/statm: 25045 23956 225 418 0 24625 0 Current children cumulated CPU time (s) 25.22 Current children cumulated vsize (KiB) 102784 [startup+51.1101 s] /proc/loadavg: 1.08 1.14 1.09 2/46 30163 /proc/meminfo: memFree=650804/1048576 swapFree=2077608/2097144 [pid=30149] ppid=30148 vsize=2604 CPUtime=3.59 /proc/30149/stat : 30149 (aspcud-trendy-1) S 30148 30149 4159 34819 4229 4202496 626 35979 0 40 0 0 346 13 18 0 1 0 883839664 2666496 301 1283457024 134512640 135304128 4287386256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30149/statm: 651 301 253 194 0 37 0 [pid=30161] ppid=30149 vsize=122820 CPUtime=47.22 /proc/30161/stat : 30161 (clasp) R 30149 30149 4159 34819 4229 4202496 34789 0 20 0 4706 16 0 0 25 0 1 0 883839669 125767680 29577 1283457024 134512640 136223643 4289605568 18446744073709551615 134929384 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30161/statm: 30705 29577 225 418 0 30285 0 Current children cumulated CPU time (s) 50.81 Current children cumulated vsize (KiB) 125424 [startup+102.305 s] /proc/loadavg: 1.03 1.12 1.08 2/46 30163 /proc/meminfo: memFree=588928/1048576 swapFree=2077608/2097144 [pid=30149] ppid=30148 vsize=2604 CPUtime=3.59 /proc/30149/stat : 30149 (aspcud-trendy-1) S 30148 30149 4159 34819 4229 4202496 626 35979 0 40 0 0 346 13 18 0 1 0 883839664 2666496 301 1283457024 134512640 135304128 4287386256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30149/statm: 651 301 253 194 0 37 0 [pid=30161] ppid=30149 vsize=182408 CPUtime=98.38 /proc/30161/stat : 30161 (clasp) R 30149 30149 4159 34819 4229 4202496 49675 0 20 0 9813 25 0 0 25 0 1 0 883839669 186785792 44463 1283457024 134512640 136223643 4289605568 18446744073709551615 134711275 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30161/statm: 45602 44463 225 418 0 45182 0 Current children cumulated CPU time (s) 101.97 Current children cumulated vsize (KiB) 185012 [startup+162.313 s] /proc/loadavg: 1.01 1.09 1.08 2/46 30163 /proc/meminfo: memFree=449304/1048576 swapFree=2077608/2097144 [pid=30149] ppid=30148 vsize=2604 CPUtime=3.59 /proc/30149/stat : 30149 (aspcud-trendy-1) S 30148 30149 4159 34819 4229 4202496 626 35979 0 40 0 0 346 13 18 0 1 0 883839664 2666496 301 1283457024 134512640 135304128 4287386256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30149/statm: 651 301 253 194 0 37 0 [pid=30161] ppid=30149 vsize=321816 CPUtime=158.34 /proc/30161/stat : 30161 (clasp) R 30149 30149 4159 34819 4229 4202496 84469 0 20 0 15794 40 0 0 25 0 1 0 883839669 329539584 79257 1283457024 134512640 136223643 4289605568 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30161/statm: 80454 79257 225 418 0 80034 0 Current children cumulated CPU time (s) 161.93 Current children cumulated vsize (KiB) 324420 [startup+222.309 s] /proc/loadavg: 1.00 1.07 1.07 2/46 30163 /proc/meminfo: memFree=307324/1048576 swapFree=2077608/2097144 [pid=30149] ppid=30148 vsize=2604 CPUtime=3.59 /proc/30149/stat : 30149 (aspcud-trendy-1) S 30148 30149 4159 34819 4229 4202496 626 35979 0 40 0 0 346 13 18 0 1 0 883839664 2666496 301 1283457024 134512640 135304128 4287386256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30149/statm: 651 301 253 194 0 37 0 [pid=30161] ppid=30149 vsize=463928 CPUtime=218.28 /proc/30161/stat : 30161 (clasp) R 30149 30149 4159 34819 4229 4202496 120122 0 20 0 21762 66 0 0 25 0 1 0 883839669 475062272 114669 1283457024 134512640 136223643 4289605568 18446744073709551615 134931000 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30161/statm: 115982 114669 225 418 0 115562 0 Current children cumulated CPU time (s) 221.87 Current children cumulated vsize (KiB) 466532 [startup+282.307 s] /proc/loadavg: 1.00 1.06 1.07 2/46 30163 /proc/meminfo: memFree=219036/1048576 swapFree=2077608/2097144 [pid=30149] ppid=30148 vsize=2604 CPUtime=3.59 /proc/30149/stat : 30149 (aspcud-trendy-1) S 30148 30149 4159 34819 4229 4202496 626 35979 0 40 0 0 346 13 18 0 1 0 883839664 2666496 301 1283457024 134512640 135304128 4287386256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30149/statm: 651 301 253 194 0 37 0 [pid=30161] ppid=30149 vsize=551736 CPUtime=278.27 /proc/30161/stat : 30161 (clasp) R 30149 30149 4159 34819 4229 4202496 142118 0 20 0 27751 76 0 0 25 0 1 0 883839669 564977664 136665 1283457024 134512640 136223643 4289605568 18446744073709551615 134929006 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30161/statm: 137934 136665 225 418 0 137514 0 Current children cumulated CPU time (s) 281.86 Current children cumulated vsize (KiB) 554340 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.509 s] /proc/loadavg: 1.00 1.06 1.06 2/46 30163 /proc/meminfo: memFree=219036/1048576 swapFree=2077608/2097144 [pid=30149] ppid=30148 vsize=2604 CPUtime=3.59 /proc/30149/stat : 30149 (aspcud-trendy-1) S 30148 30149 4159 34819 4229 4202496 626 35979 0 40 0 0 346 13 18 0 1 0 883839664 2666496 301 1283457024 134512640 135304128 4287386256 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30149/statm: 651 301 253 194 0 37 0 [pid=30161] ppid=30149 vsize=551736 CPUtime=286.47 /proc/30161/stat : 30161 (clasp) R 30149 30149 4159 34819 4229 4202496 142119 0 20 0 28571 76 0 0 25 0 1 0 883839669 564977664 136666 1283457024 134512640 136223643 4289605568 18446744073709551615 134928897 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/30161/statm: 137934 136666 225 418 0 137514 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 554340 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.575 CPU time (s): 290.122 CPU user time (s): 289.178 CPU system time (s): 0.944059 CPU usage (%): 99.8443 Max. virtual memory (cumulated for all children) (KiB): 554340 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.178 system time used= 0.944059 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 181336 page faults= 61 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 3021 involuntary context switches= 5965 runsolver used 0 second user time and 0 second system time The end