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/201108311143/aspcud-1.5/rand152.cudf.user-upgrades.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/user-upgrades/rand152.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/rand152.cudf.user-upgrades.result -sum(installedsize) 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 1.03 1.00 3/37 20799 /proc/meminfo: memFree=788960/1048576 swapFree=0/0 [pid=20798] ppid=20797 vsize=2588 CPUtime=0 /proc/20798/stat : 20798 (aspcud-1.5) R 20797 20798 19908 34817 19908 4202496 365 0 0 0 0 0 0 0 25 0 1 0 61205332 2650112 279 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/20798/statm: 647 279 234 194 0 34 0 [pid=20799] ppid=20798 vsize=2588 CPUtime=0 /proc/20799/stat : 20799 (aspcud-1.5) R 20798 20798 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 61205332 2650112 45 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/20799/statm: 647 45 0 194 0 34 0 [startup+0.142657 s] /proc/loadavg: 0.99 1.03 1.00 3/37 20799 /proc/meminfo: memFree=788960/1048576 swapFree=0/0 [pid=20798] ppid=20797 vsize=2596 CPUtime=0 /proc/20798/stat : 20798 (aspcud-1.5) S 20797 20798 19908 34817 19908 4202496 580 1522 0 0 0 0 0 0 25 0 1 0 61205332 2658304 298 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20798/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.206707 s] /proc/loadavg: 0.99 1.03 1.00 3/37 20799 /proc/meminfo: memFree=788960/1048576 swapFree=0/0 [pid=20798] ppid=20797 vsize=2596 CPUtime=0 /proc/20798/stat : 20798 (aspcud-1.5) S 20797 20798 19908 34817 19908 4202496 580 1522 0 0 0 0 0 0 25 0 1 0 61205332 2658304 298 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20798/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.306676 s] /proc/loadavg: 0.99 1.03 1.00 3/37 20799 /proc/meminfo: memFree=788960/1048576 swapFree=0/0 [pid=20798] ppid=20797 vsize=2596 CPUtime=0 /proc/20798/stat : 20798 (aspcud-1.5) S 20797 20798 19908 34817 19908 4202496 580 1522 0 0 0 0 0 0 25 0 1 0 61205332 2658304 298 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20798/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.706703 s] /proc/loadavg: 0.99 1.03 1.00 3/37 20799 /proc/meminfo: memFree=788960/1048576 swapFree=0/0 [pid=20798] ppid=20797 vsize=2596 CPUtime=0 /proc/20798/stat : 20798 (aspcud-1.5) S 20797 20798 19908 34817 19908 4202496 580 1522 0 0 0 0 0 0 25 0 1 0 61205332 2658304 298 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20798/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50676 s] /proc/loadavg: 0.99 1.03 1.00 2/40 20809 /proc/meminfo: memFree=759696/1048576 swapFree=0/0 [pid=20798] ppid=20797 vsize=2596 CPUtime=0 /proc/20798/stat : 20798 (aspcud-1.5) S 20797 20798 19908 34817 19908 4202496 580 1522 0 0 0 0 0 0 25 0 1 0 61205332 2658304 298 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20798/statm: 649 298 251 194 0 36 0 [pid=20807] ppid=20798 vsize=1928 CPUtime=0 /proc/20807/stat : 20807 (clasp) S 20798 20798 19908 34817 19908 4202496 291 0 0 0 0 0 0 0 25 0 1 0 61205333 1974272 159 1283457024 134512640 136285277 4293847280 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/20807/statm: 482 159 144 433 0 47 0 [pid=20808] ppid=20798 vsize=2584 CPUtime=0 /proc/20808/stat : 20808 (gringo) S 20798 20798 19908 34817 19908 4202496 404 0 0 0 0 0 0 0 25 0 1 0 61205333 2646016 272 1283457024 134512640 136933539 4289367328 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/20808/statm: 646 272 242 592 0 51 0 [pid=20809] ppid=20798 vsize=28116 CPUtime=1.11 /proc/20809/stat : 20809 (cudf2lp) R 20798 20798 19908 34817 19908 4202496 7950 0 0 0 107 4 0 0 25 0 1 0 61205333 28790784 6206 1283457024 134512640 135786343 4292855936 18446744073709551615 135208297 0 0 6 0 0 0 0 17 0 0 0 0 /proc/20809/statm: 7029 6206 128 311 0 6716 0 Current children cumulated CPU time (s) 1.11 Current children cumulated vsize (KiB) 35224 [startup+3.11109 s] /proc/loadavg: 0.99 1.03 1.00 2/40 20809 /proc/meminfo: memFree=729976/1048576 swapFree=0/0 [pid=20798] ppid=20797 vsize=2596 CPUtime=2.15 /proc/20798/stat : 20798 (aspcud-1.5) R 20797 20798 19908 34817 19908 4202496 580 15496 0 0 0 0 208 7 19 0 1 0 61205332 2658304 298 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/20798/statm: 649 298 251 194 0 36 0 [pid=20807] ppid=20798 vsize=3764 CPUtime=0.4 /proc/20807/stat : 20807 (clasp) R 20798 20798 19908 34817 19908 4202496 835 0 0 0 40 0 0 0 18 0 1 0 61205333 3854336 703 1283457024 134512640 136285277 4293847280 18446744073709551615 134952445 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20807/statm: 941 703 233 433 0 506 0 [pid=20808] ppid=20798 vsize=0 CPUtime=0.05 /proc/20808/stat : 20808 (gringo) Z 20798 20798 19908 34817 19908 4202508 911 0 0 0 5 0 0 0 18 0 1 0 61205333 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/20808/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.6 Current children cumulated vsize (KiB) 6360 [startup+6.31171 s] /proc/loadavg: 0.99 1.03 1.00 2/38 20809 /proc/meminfo: memFree=755868/1048576 swapFree=0/0 [pid=20798] ppid=20797 vsize=2596 CPUtime=2.21 /proc/20798/stat : 20798 (aspcud-1.5) S 20797 20798 19908 34817 19908 4202496 580 16407 0 0 0 0 214 7 17 0 1 0 61205332 2658304 298 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20798/statm: 649 298 251 194 0 36 0 [pid=20807] ppid=20798 vsize=4384 CPUtime=3.6 /proc/20807/stat : 20807 (clasp) R 20798 20798 19908 34817 19908 4202496 1018 0 0 0 360 0 0 0 25 0 1 0 61205333 4489216 886 1283457024 134512640 136285277 4293847280 18446744073709551615 134930836 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20807/statm: 1096 886 234 433 0 661 0 Current children cumulated CPU time (s) 5.81 Current children cumulated vsize (KiB) 6980 [startup+12.7131 s] /proc/loadavg: 0.99 1.03 1.00 2/38 20809 /proc/meminfo: memFree=755248/1048576 swapFree=0/0 [pid=20798] ppid=20797 vsize=2596 CPUtime=2.21 /proc/20798/stat : 20798 (aspcud-1.5) S 20797 20798 19908 34817 19908 4202496 580 16407 0 0 0 0 214 7 17 0 1 0 61205332 2658304 298 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20798/statm: 649 298 251 194 0 36 0 [pid=20807] ppid=20798 vsize=4780 CPUtime=10 /proc/20807/stat : 20807 (clasp) R 20798 20798 19908 34817 19908 4202496 1113 0 0 0 1000 0 0 0 25 0 1 0 61205333 4894720 981 1283457024 134512640 136285277 4293847280 18446744073709551615 134735717 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20807/statm: 1195 981 234 433 0 760 0 Current children cumulated CPU time (s) 12.21 Current children cumulated vsize (KiB) 7376 [startup+25.5059 s] /proc/loadavg: 0.99 1.03 1.00 2/38 20809 /proc/meminfo: memFree=754876/1048576 swapFree=0/0 [pid=20798] ppid=20797 vsize=2596 CPUtime=2.21 /proc/20798/stat : 20798 (aspcud-1.5) S 20797 20798 19908 34817 19908 4202496 580 16407 0 0 0 0 214 7 17 0 1 0 61205332 2658304 298 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20798/statm: 649 298 251 194 0 36 0 [pid=20807] ppid=20798 vsize=5256 CPUtime=22.78 /proc/20807/stat : 20807 (clasp) R 20798 20798 19908 34817 19908 4202496 1221 0 0 0 2278 0 0 0 25 0 1 0 61205333 5382144 1082 1283457024 134512640 136285277 4293847280 18446744073709551615 134963467 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20807/statm: 1314 1082 234 433 0 879 0 Current children cumulated CPU time (s) 24.99 Current children cumulated vsize (KiB) 7852 [startup+51.1116 s] /proc/loadavg: 0.99 1.02 1.00 2/38 20809 /proc/meminfo: memFree=754628/1048576 swapFree=0/0 [pid=20798] ppid=20797 vsize=2596 CPUtime=2.21 /proc/20798/stat : 20798 (aspcud-1.5) S 20797 20798 19908 34817 19908 4202496 580 16407 0 0 0 0 214 7 17 0 1 0 61205332 2658304 298 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20798/statm: 649 298 251 194 0 36 0 [pid=20807] ppid=20798 vsize=5444 CPUtime=48.39 /proc/20807/stat : 20807 (clasp) R 20798 20798 19908 34817 19908 4202496 1286 0 0 0 4839 0 0 0 25 0 1 0 61205333 5574656 1147 1283457024 134512640 136285277 4293847280 18446744073709551615 134959552 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20807/statm: 1361 1147 234 433 0 926 0 Current children cumulated CPU time (s) 50.6 Current children cumulated vsize (KiB) 8040 [startup+102.313 s] /proc/loadavg: 0.99 1.02 1.00 2/38 20809 /proc/meminfo: memFree=754132/1048576 swapFree=0/0 [pid=20798] ppid=20797 vsize=2596 CPUtime=2.21 /proc/20798/stat : 20798 (aspcud-1.5) S 20797 20798 19908 34817 19908 4202496 580 16407 0 0 0 0 214 7 17 0 1 0 61205332 2658304 298 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20798/statm: 649 298 251 194 0 36 0 [pid=20807] ppid=20798 vsize=5712 CPUtime=99.55 /proc/20807/stat : 20807 (clasp) R 20798 20798 19908 34817 19908 4202496 1409 0 0 0 9953 2 0 0 25 0 1 0 61205333 5849088 1223 1283457024 134512640 136285277 4293847280 18446744073709551615 134930655 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20807/statm: 1428 1223 234 433 0 993 0 Current children cumulated CPU time (s) 101.76 Current children cumulated vsize (KiB) 8308 [startup+162.307 s] /proc/loadavg: 0.99 1.01 1.00 2/38 20809 /proc/meminfo: memFree=753884/1048576 swapFree=0/0 [pid=20798] ppid=20797 vsize=2596 CPUtime=2.21 /proc/20798/stat : 20798 (aspcud-1.5) S 20797 20798 19908 34817 19908 4202496 580 16407 0 0 0 0 214 7 17 0 1 0 61205332 2658304 298 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20798/statm: 649 298 251 194 0 36 0 [pid=20807] ppid=20798 vsize=6016 CPUtime=159.51 /proc/20807/stat : 20807 (clasp) R 20798 20798 19908 34817 19908 4202496 1481 0 0 0 15949 2 0 0 25 0 1 0 61205333 6160384 1295 1283457024 134512640 136285277 4293847280 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20807/statm: 1504 1295 234 433 0 1069 0 Current children cumulated CPU time (s) 161.72 Current children cumulated vsize (KiB) 8612 [startup+222.309 s] /proc/loadavg: 0.99 1.01 1.00 2/38 20809 /proc/meminfo: memFree=753760/1048576 swapFree=0/0 [pid=20798] ppid=20797 vsize=2596 CPUtime=2.21 /proc/20798/stat : 20798 (aspcud-1.5) S 20797 20798 19908 34817 19908 4202496 580 16407 0 0 0 0 214 7 17 0 1 0 61205332 2658304 298 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20798/statm: 649 298 251 194 0 36 0 [pid=20807] ppid=20798 vsize=6128 CPUtime=219.48 /proc/20807/stat : 20807 (clasp) R 20798 20798 19908 34817 19908 4202496 1601 0 0 0 21946 2 0 0 25 0 1 0 61205333 6275072 1327 1283457024 134512640 136285277 4293847280 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20807/statm: 1532 1327 234 433 0 1097 0 Current children cumulated CPU time (s) 221.69 Current children cumulated vsize (KiB) 8724 [startup+282.312 s] /proc/loadavg: 0.99 1.00 1.00 2/40 20815 /proc/meminfo: memFree=753488/1048576 swapFree=0/0 [pid=20798] ppid=20797 vsize=2596 CPUtime=2.21 /proc/20798/stat : 20798 (aspcud-1.5) S 20797 20798 19908 34817 19908 4202496 580 16407 0 0 0 0 214 7 17 0 1 0 61205332 2658304 298 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20798/statm: 649 298 251 194 0 36 0 [pid=20807] ppid=20798 vsize=6200 CPUtime=279.45 /proc/20807/stat : 20807 (clasp) R 20798 20798 19908 34817 19908 4202496 1642 0 0 0 27943 2 0 0 25 0 1 0 61205333 6348800 1345 1283457024 134512640 136285277 4293847280 18446744073709551615 134948733 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20807/statm: 1550 1345 234 433 0 1115 0 Current children cumulated CPU time (s) 281.66 Current children cumulated vsize (KiB) 8796 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.714 s] /proc/loadavg: 0.99 1.00 1.00 2/40 20816 /proc/meminfo: memFree=753488/1048576 swapFree=0/0 [pid=20798] ppid=20797 vsize=2596 CPUtime=2.21 /proc/20798/stat : 20798 (aspcud-1.5) S 20797 20798 19908 34817 19908 4202496 580 16407 0 0 0 0 214 7 17 0 1 0 61205332 2658304 298 1283457024 134512640 135304128 4288412640 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20798/statm: 649 298 251 194 0 36 0 [pid=20807] ppid=20798 vsize=6200 CPUtime=287.85 /proc/20807/stat : 20807 (clasp) R 20798 20798 19908 34817 19908 4202496 1642 0 0 0 28783 2 0 0 25 0 1 0 61205333 6348800 1345 1283457024 134512640 136285277 4293847280 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20807/statm: 1550 1345 234 433 0 1115 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 8796 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.733 CPU time (s): 290.086 CPU user time (s): 289.974 CPU system time (s): 0.112007 CPU usage (%): 99.7773 Max. virtual memory (cumulated for all children) (KiB): 54800 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.974 system time used= 0.112007 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 22177 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= 183 involuntary context switches= 3691 runsolver used 0 second user time and 0.012 second system time The end