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/rand924.cudf.user-upgrades.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/user-upgrades/rand924.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/rand924.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: 1.01 1.01 1.00 5/36 29646 /proc/meminfo: memFree=643680/1048576 swapFree=0/0 [pid=29644] ppid=29643 vsize=2588 CPUtime=0 /proc/29644/stat : 29644 (aspcud-1.5) S 29643 29644 19908 34817 19908 4202496 374 0 0 0 0 0 0 0 18 0 1 0 65591462 2650112 280 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/29644/statm: 647 280 234 194 0 34 0 [pid=29645] ppid=29644 vsize=2588 CPUtime=0 /proc/29645/stat : 29645 (aspcud-1.5) S 29644 29644 19908 34817 19908 4202560 119 0 0 0 0 0 0 0 25 0 1 0 65591462 2650112 134 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/29645/statm: 647 134 87 194 0 34 0 [pid=29646] ppid=29645 vsize=2588 CPUtime=0 /proc/29646/stat : 29646 (aspcud-1.5) R 29645 29644 19908 34817 19908 4202560 127 0 0 0 0 0 0 0 25 0 1 0 65591462 2650112 151 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/29646/statm: 647 151 104 194 0 34 0 [pid=29647] ppid=29646 vsize=2588 CPUtime=0 /proc/29647/stat : 29647 (aspcud-1.5) R 29646 29644 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 65591463 2650112 47 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/29647/statm: 647 47 0 194 0 34 0 [startup+0.144926 s] /proc/loadavg: 1.01 1.01 1.00 5/36 29646 /proc/meminfo: memFree=643680/1048576 swapFree=0/0 [pid=29644] ppid=29643 vsize=2596 CPUtime=0 /proc/29644/stat : 29644 (aspcud-1.5) S 29643 29644 19908 34817 19908 4202496 581 1519 0 0 0 0 0 0 25 0 1 0 65591462 2658304 299 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29644/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.204953 s] /proc/loadavg: 1.01 1.01 1.00 5/36 29646 /proc/meminfo: memFree=643680/1048576 swapFree=0/0 [pid=29644] ppid=29643 vsize=2596 CPUtime=0 /proc/29644/stat : 29644 (aspcud-1.5) S 29643 29644 19908 34817 19908 4202496 581 1519 0 0 0 0 0 0 25 0 1 0 65591462 2658304 299 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29644/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.304944 s] /proc/loadavg: 1.01 1.01 1.00 5/36 29646 /proc/meminfo: memFree=643680/1048576 swapFree=0/0 [pid=29644] ppid=29643 vsize=2596 CPUtime=0 /proc/29644/stat : 29644 (aspcud-1.5) S 29643 29644 19908 34817 19908 4202496 581 1519 0 0 0 0 0 0 25 0 1 0 65591462 2658304 299 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29644/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.709542 s] /proc/loadavg: 1.01 1.01 1.00 5/36 29646 /proc/meminfo: memFree=643680/1048576 swapFree=0/0 [pid=29644] ppid=29643 vsize=2596 CPUtime=0 /proc/29644/stat : 29644 (aspcud-1.5) S 29643 29644 19908 34817 19908 4202496 581 1519 0 0 0 0 0 0 25 0 1 0 65591462 2658304 299 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29644/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50501 s] /proc/loadavg: 1.01 1.01 1.00 2/38 29655 /proc/meminfo: memFree=611432/1048576 swapFree=0/0 [pid=29644] ppid=29643 vsize=2596 CPUtime=0 /proc/29644/stat : 29644 (aspcud-1.5) S 29643 29644 19908 34817 19908 4202496 581 1519 0 0 0 0 0 0 25 0 1 0 65591462 2658304 299 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29644/statm: 649 299 251 194 0 36 0 [pid=29653] ppid=29644 vsize=1932 CPUtime=0 /proc/29653/stat : 29653 (clasp) S 29644 29644 19908 34817 19908 4202496 293 0 0 0 0 0 0 0 25 0 1 0 65591463 1978368 160 1283457024 134512640 136285277 4290467248 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/29653/statm: 483 160 144 433 0 48 0 [pid=29654] ppid=29644 vsize=2584 CPUtime=0 /proc/29654/stat : 29654 (gringo) S 29644 29644 19908 34817 19908 4202496 405 0 0 0 0 0 0 0 25 0 1 0 65591463 2646016 272 1283457024 134512640 136933539 4291977120 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/29654/statm: 646 272 242 592 0 51 0 [pid=29655] ppid=29644 vsize=28116 CPUtime=1.29 /proc/29655/stat : 29655 (cudf2lp) R 29644 29644 19908 34817 19908 4202496 8008 0 0 0 124 5 0 0 25 0 1 0 65591463 28790784 6263 1283457024 134512640 135786343 4291417888 18446744073709551615 134614880 0 0 6 0 0 0 0 17 0 0 0 0 /proc/29655/statm: 7029 6263 128 311 0 6716 0 Current children cumulated CPU time (s) 1.29 Current children cumulated vsize (KiB) 35228 [startup+3.112 s] /proc/loadavg: 1.01 1.01 1.00 2/38 29655 /proc/meminfo: memFree=574180/1048576 swapFree=0/0 [pid=29644] ppid=29643 vsize=2596 CPUtime=2.36 /proc/29644/stat : 29644 (aspcud-1.5) R 29643 29644 19908 34817 19908 4202496 581 15494 0 0 0 0 226 10 19 0 1 0 65591462 2658304 299 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/29644/statm: 649 299 251 194 0 36 0 [pid=29653] ppid=29644 vsize=3752 CPUtime=0.47 /proc/29653/stat : 29653 (clasp) R 29644 29644 19908 34817 19908 4202496 856 0 0 0 47 0 0 0 18 0 1 0 65591463 3842048 719 1283457024 134512640 136285277 4290467248 18446744073709551615 134960075 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29653/statm: 938 719 233 433 0 503 0 [pid=29654] ppid=29644 vsize=0 CPUtime=0.02 /proc/29654/stat : 29654 (gringo) Z 29644 29644 19908 34817 19908 4202508 908 0 0 0 2 0 0 0 18 0 1 0 65591463 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/29654/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.85 Current children cumulated vsize (KiB) 6348 [startup+6.3124 s] /proc/loadavg: 1.01 1.01 1.00 2/36 29655 /proc/meminfo: memFree=610676/1048576 swapFree=0/0 [pid=29644] ppid=29643 vsize=2596 CPUtime=2.38 /proc/29644/stat : 29644 (aspcud-1.5) S 29643 29644 19908 34817 19908 4202496 581 16402 0 0 0 0 228 10 17 0 1 0 65591462 2658304 299 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29644/statm: 649 299 251 194 0 36 0 [pid=29653] ppid=29644 vsize=4296 CPUtime=3.66 /proc/29653/stat : 29653 (clasp) R 29644 29644 19908 34817 19908 4202496 1000 0 0 0 366 0 0 0 25 0 1 0 65591463 4399104 863 1283457024 134512640 136285277 4290467248 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29653/statm: 1074 863 234 433 0 639 0 Current children cumulated CPU time (s) 6.04 Current children cumulated vsize (KiB) 6892 [startup+12.7134 s] /proc/loadavg: 1.01 1.01 1.00 2/36 29655 /proc/meminfo: memFree=610180/1048576 swapFree=0/0 [pid=29644] ppid=29643 vsize=2596 CPUtime=2.38 /proc/29644/stat : 29644 (aspcud-1.5) S 29643 29644 19908 34817 19908 4202496 581 16402 0 0 0 0 228 10 17 0 1 0 65591462 2658304 299 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29644/statm: 649 299 251 194 0 36 0 [pid=29653] ppid=29644 vsize=4752 CPUtime=10.06 /proc/29653/stat : 29653 (clasp) R 29644 29644 19908 34817 19908 4202496 1105 0 0 0 1006 0 0 0 25 0 1 0 65591463 4866048 968 1283457024 134512640 136285277 4290467248 18446744073709551615 134963435 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29653/statm: 1188 968 234 433 0 753 0 Current children cumulated CPU time (s) 12.44 Current children cumulated vsize (KiB) 7348 [startup+25.506 s] /proc/loadavg: 1.01 1.01 1.00 2/36 29655 /proc/meminfo: memFree=609808/1048576 swapFree=0/0 [pid=29644] ppid=29643 vsize=2596 CPUtime=2.38 /proc/29644/stat : 29644 (aspcud-1.5) S 29643 29644 19908 34817 19908 4202496 581 16402 0 0 0 0 228 10 17 0 1 0 65591462 2658304 299 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29644/statm: 649 299 251 194 0 36 0 [pid=29653] ppid=29644 vsize=5116 CPUtime=22.85 /proc/29653/stat : 29653 (clasp) R 29644 29644 19908 34817 19908 4202496 1211 0 0 0 2285 0 0 0 25 0 1 0 65591463 5238784 1066 1283457024 134512640 136285277 4290467248 18446744073709551615 134963519 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29653/statm: 1279 1066 234 433 0 844 0 Current children cumulated CPU time (s) 25.23 Current children cumulated vsize (KiB) 7712 [startup+51.1101 s] /proc/loadavg: 1.00 1.00 1.00 2/35 29655 /proc/meminfo: memFree=609072/1048576 swapFree=0/0 [pid=29644] ppid=29643 vsize=2596 CPUtime=2.38 /proc/29644/stat : 29644 (aspcud-1.5) S 29643 29644 19908 34817 19908 4202496 581 16402 0 0 0 0 228 10 17 0 1 0 65591462 2658304 299 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29644/statm: 649 299 251 194 0 36 0 [pid=29653] ppid=29644 vsize=5772 CPUtime=48.45 /proc/29653/stat : 29653 (clasp) R 29644 29644 19908 34817 19908 4202496 1411 0 0 0 4844 1 0 0 25 0 1 0 65591463 5910528 1230 1283457024 134512640 136285277 4290467248 18446744073709551615 134733705 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29653/statm: 1443 1230 234 433 0 1008 0 Current children cumulated CPU time (s) 50.83 Current children cumulated vsize (KiB) 8368 [startup+102.313 s] /proc/loadavg: 1.00 1.00 1.00 2/35 29655 /proc/meminfo: memFree=608824/1048576 swapFree=0/0 [pid=29644] ppid=29643 vsize=2596 CPUtime=2.38 /proc/29644/stat : 29644 (aspcud-1.5) S 29643 29644 19908 34817 19908 4202496 581 16402 0 0 0 0 228 10 17 0 1 0 65591462 2658304 299 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29644/statm: 649 299 251 194 0 36 0 [pid=29653] ppid=29644 vsize=6040 CPUtime=99.65 /proc/29653/stat : 29653 (clasp) R 29644 29644 19908 34817 19908 4202496 1494 0 0 0 9964 1 0 0 25 0 1 0 65591463 6184960 1293 1283457024 134512640 136285277 4290467248 18446744073709551615 134669813 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29653/statm: 1510 1293 234 433 0 1075 0 Current children cumulated CPU time (s) 102.03 Current children cumulated vsize (KiB) 8636 [startup+162.307 s] /proc/loadavg: 1.00 1.00 1.00 2/37 29662 /proc/meminfo: memFree=608180/1048576 swapFree=0/0 [pid=29644] ppid=29643 vsize=2596 CPUtime=2.38 /proc/29644/stat : 29644 (aspcud-1.5) S 29643 29644 19908 34817 19908 4202496 581 16402 0 0 0 0 228 10 17 0 1 0 65591462 2658304 299 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29644/statm: 649 299 251 194 0 36 0 [pid=29653] ppid=29644 vsize=6456 CPUtime=159.58 /proc/29653/stat : 29653 (clasp) R 29644 29644 19908 34817 19908 4202496 1615 0 0 0 15957 1 0 0 25 0 1 0 65591463 6610944 1391 1283457024 134512640 136285277 4290467248 18446744073709551615 134735672 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29653/statm: 1614 1391 234 433 0 1179 0 Current children cumulated CPU time (s) 161.96 Current children cumulated vsize (KiB) 9052 [startup+222.309 s] /proc/loadavg: 1.00 1.00 1.00 2/36 29666 /proc/meminfo: memFree=608072/1048576 swapFree=0/0 [pid=29644] ppid=29643 vsize=2596 CPUtime=2.38 /proc/29644/stat : 29644 (aspcud-1.5) S 29643 29644 19908 34817 19908 4202496 581 16402 0 0 0 0 228 10 17 0 1 0 65591462 2658304 299 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29644/statm: 649 299 251 194 0 36 0 [pid=29653] ppid=29644 vsize=6672 CPUtime=219.56 /proc/29653/stat : 29653 (clasp) R 29644 29644 19908 34817 19908 4202496 1678 0 0 0 21954 2 0 0 25 0 1 0 65591463 6832128 1444 1283457024 134512640 136285277 4290467248 18446744073709551615 134670204 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29653/statm: 1668 1444 234 433 0 1233 0 Current children cumulated CPU time (s) 221.94 Current children cumulated vsize (KiB) 9268 [startup+282.311 s] /proc/loadavg: 1.00 1.00 1.00 2/35 29666 /proc/meminfo: memFree=608080/1048576 swapFree=0/0 [pid=29644] ppid=29643 vsize=2596 CPUtime=2.38 /proc/29644/stat : 29644 (aspcud-1.5) S 29643 29644 19908 34817 19908 4202496 581 16402 0 0 0 0 228 10 17 0 1 0 65591462 2658304 299 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29644/statm: 649 299 251 194 0 36 0 [pid=29653] ppid=29644 vsize=6672 CPUtime=279.54 /proc/29653/stat : 29653 (clasp) R 29644 29644 19908 34817 19908 4202496 1681 0 0 0 27952 2 0 0 25 0 1 0 65591463 6832128 1447 1283457024 134512640 136285277 4290467248 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29653/statm: 1668 1447 234 433 0 1233 0 Current children cumulated CPU time (s) 281.92 Current children cumulated vsize (KiB) 9268 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.413 s] /proc/loadavg: 1.00 1.00 1.00 2/35 29666 /proc/meminfo: memFree=608080/1048576 swapFree=0/0 [pid=29644] ppid=29643 vsize=2596 CPUtime=2.38 /proc/29644/stat : 29644 (aspcud-1.5) S 29643 29644 19908 34817 19908 4202496 581 16402 0 0 0 0 228 10 17 0 1 0 65591462 2658304 299 1283457024 134512640 135304128 4291376816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29644/statm: 649 299 251 194 0 36 0 [pid=29653] ppid=29644 vsize=6672 CPUtime=287.64 /proc/29653/stat : 29653 (clasp) R 29644 29644 19908 34817 19908 4202496 1681 0 0 0 28762 2 0 0 25 0 1 0 65591463 6832128 1447 1283457024 134512640 136285277 4290467248 18446744073709551615 134615133 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29653/statm: 1668 1447 234 433 0 1233 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 9268 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.434 CPU time (s): 290.054 CPU user time (s): 289.91 CPU system time (s): 0.144009 CPU usage (%): 99.8693 Max. virtual memory (cumulated for all children) (KiB): 53220 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.91 system time used= 0.144009 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 22224 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= 190 involuntary context switches= 3721 runsolver used 0 second user time and 0.008 second system time The end