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/rand437.cudf.user-upgrades.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/user-upgrades/rand437.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/rand437.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.39 1.14 1.04 5/38 24449 /proc/meminfo: memFree=584700/1048576 swapFree=0/0 [pid=24447] ppid=24446 vsize=2588 CPUtime=0 /proc/24447/stat : 24447 (aspcud-1.5) S 24446 24447 19908 34817 19908 4202496 373 0 0 0 0 0 0 0 18 0 1 0 62939864 2650112 280 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/24447/statm: 647 280 234 194 0 34 0 [pid=24448] ppid=24447 vsize=2588 CPUtime=0 /proc/24448/stat : 24448 (aspcud-1.5) R 24447 24447 19908 34817 19908 4202560 110 0 0 0 0 0 0 0 25 0 1 0 62939864 2650112 133 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/24448/statm: 647 133 86 194 0 34 0 [pid=24449] ppid=24448 vsize=2588 CPUtime=0 /proc/24449/stat : 24449 (aspcud-1.5) R 24448 24447 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 62939864 2650112 47 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/24449/statm: 647 47 0 194 0 34 0 [startup+0.122758 s] /proc/loadavg: 1.39 1.14 1.04 5/38 24449 /proc/meminfo: memFree=584700/1048576 swapFree=0/0 [pid=24447] ppid=24446 vsize=2596 CPUtime=0 /proc/24447/stat : 24447 (aspcud-1.5) S 24446 24447 19908 34817 19908 4202496 581 1520 0 0 0 0 0 0 25 0 1 0 62939864 2658304 299 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24447/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.206659 s] /proc/loadavg: 1.39 1.14 1.04 5/38 24449 /proc/meminfo: memFree=584700/1048576 swapFree=0/0 [pid=24447] ppid=24446 vsize=2596 CPUtime=0 /proc/24447/stat : 24447 (aspcud-1.5) S 24446 24447 19908 34817 19908 4202496 581 1520 0 0 0 0 0 0 25 0 1 0 62939864 2658304 299 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24447/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.306815 s] /proc/loadavg: 1.39 1.14 1.04 5/38 24449 /proc/meminfo: memFree=584700/1048576 swapFree=0/0 [pid=24447] ppid=24446 vsize=2596 CPUtime=0 /proc/24447/stat : 24447 (aspcud-1.5) S 24446 24447 19908 34817 19908 4202496 581 1520 0 0 0 0 0 0 25 0 1 0 62939864 2658304 299 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24447/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.706709 s] /proc/loadavg: 1.39 1.14 1.04 5/38 24449 /proc/meminfo: memFree=584700/1048576 swapFree=0/0 [pid=24447] ppid=24446 vsize=2596 CPUtime=0 /proc/24447/stat : 24447 (aspcud-1.5) S 24446 24447 19908 34817 19908 4202496 581 1520 0 0 0 0 0 0 25 0 1 0 62939864 2658304 299 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24447/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50675 s] /proc/loadavg: 1.36 1.13 1.04 2/40 24458 /proc/meminfo: memFree=561316/1048576 swapFree=0/0 [pid=24447] ppid=24446 vsize=2596 CPUtime=0 /proc/24447/stat : 24447 (aspcud-1.5) S 24446 24447 19908 34817 19908 4202496 581 1520 0 0 0 0 0 0 25 0 1 0 62939864 2658304 299 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24447/statm: 649 299 251 194 0 36 0 [pid=24456] ppid=24447 vsize=1928 CPUtime=0 /proc/24456/stat : 24456 (clasp) S 24447 24447 19908 34817 19908 4202496 293 0 0 0 0 0 0 0 25 0 1 0 62939865 1974272 160 1283457024 134512640 136285277 4291690208 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/24456/statm: 482 160 144 433 0 47 0 [pid=24457] ppid=24447 vsize=2584 CPUtime=0 /proc/24457/stat : 24457 (gringo) S 24447 24447 19908 34817 19908 4202496 405 0 0 0 0 0 0 0 25 0 1 0 62939865 2646016 272 1283457024 134512640 136933539 4293583136 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/24457/statm: 646 272 242 592 0 51 0 [pid=24458] ppid=24447 vsize=16988 CPUtime=0.8 /proc/24458/stat : 24458 (cudf2lp) R 24447 24447 19908 34817 19908 4202496 4820 0 0 0 77 3 0 0 25 0 1 0 62939865 17395712 3974 1283457024 134512640 135786343 4293144768 18446744073709551615 135208478 0 0 6 0 0 0 0 17 0 0 0 0 /proc/24458/statm: 4247 3974 128 311 0 3934 0 Current children cumulated CPU time (s) 0.8 Current children cumulated vsize (KiB) 24096 [startup+3.1043 s] /proc/loadavg: 1.36 1.13 1.04 1/40 24458 /proc/meminfo: memFree=534476/1048576 swapFree=0/0 [pid=24447] ppid=24446 vsize=2596 CPUtime=2.18 /proc/24447/stat : 24447 (aspcud-1.5) S 24446 24447 19908 34817 19908 4202496 581 15495 0 0 0 0 212 6 18 0 1 0 62939864 2658304 299 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24447/statm: 649 299 251 194 0 36 0 [pid=24456] ppid=24447 vsize=3196 CPUtime=0 /proc/24456/stat : 24456 (clasp) R 24447 24447 19908 34817 19908 4202496 649 0 0 0 0 0 0 0 18 0 1 0 62939865 3272704 516 1283457024 134512640 136285277 4291690208 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24456/statm: 799 516 176 433 0 364 0 [pid=24457] ppid=24447 vsize=5576 CPUtime=0.07 /proc/24457/stat : 24457 (gringo) R 24447 24447 19908 34817 19908 4202496 1132 0 0 0 7 0 0 0 18 0 1 0 62939865 5709824 901 1283457024 134512640 136933539 4293583136 18446744073709551615 134611495 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24457/statm: 1394 901 253 592 0 799 0 Current children cumulated CPU time (s) 2.25 Current children cumulated vsize (KiB) 11368 heavy processes: [startup+6.30494 s] /proc/loadavg: 1.36 1.13 1.04 2/38 24458 /proc/meminfo: memFree=548524/1048576 swapFree=0/0 [pid=24447] ppid=24446 vsize=2596 CPUtime=2.28 /proc/24447/stat : 24447 (aspcud-1.5) S 24446 24447 19908 34817 19908 4202496 581 16872 0 0 0 0 222 6 16 0 1 0 62939864 2658304 299 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24447/statm: 649 299 251 194 0 36 0 [pid=24456] ppid=24447 vsize=7712 CPUtime=3.16 /proc/24456/stat : 24456 (clasp) R 24447 24447 19908 34817 19908 4202496 1856 0 0 0 316 0 0 0 25 0 1 0 62939865 7897088 1713 1283457024 134512640 136285277 4291690208 18446744073709551615 134642035 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24456/statm: 1928 1713 234 433 0 1493 0 Current children cumulated CPU time (s) 5.44 Current children cumulated vsize (KiB) 10308 [startup+12.7062 s] /proc/loadavg: 1.30 1.13 1.04 2/38 24458 /proc/meminfo: memFree=547904/1048576 swapFree=0/0 [pid=24447] ppid=24446 vsize=2596 CPUtime=2.28 /proc/24447/stat : 24447 (aspcud-1.5) S 24446 24447 19908 34817 19908 4202496 581 16872 0 0 0 0 222 6 16 0 1 0 62939864 2658304 299 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24447/statm: 649 299 251 194 0 36 0 [pid=24456] ppid=24447 vsize=8248 CPUtime=9.56 /proc/24456/stat : 24456 (clasp) R 24447 24447 19908 34817 19908 4202496 2008 0 0 0 956 0 0 0 25 0 1 0 62939865 8445952 1854 1283457024 134512640 136285277 4291690208 18446744073709551615 134960029 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24456/statm: 2062 1854 234 433 0 1627 0 Current children cumulated CPU time (s) 11.84 Current children cumulated vsize (KiB) 10844 [startup+25.5117 s] /proc/loadavg: 1.26 1.12 1.04 2/38 24458 /proc/meminfo: memFree=546664/1048576 swapFree=0/0 [pid=24447] ppid=24446 vsize=2596 CPUtime=2.28 /proc/24447/stat : 24447 (aspcud-1.5) S 24446 24447 19908 34817 19908 4202496 581 16872 0 0 0 0 222 6 16 0 1 0 62939864 2658304 299 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24447/statm: 649 299 251 194 0 36 0 [pid=24456] ppid=24447 vsize=9500 CPUtime=22.35 /proc/24456/stat : 24456 (clasp) R 24447 24447 19908 34817 19908 4202496 2343 0 0 0 2235 0 0 0 25 0 1 0 62939865 9728000 2152 1283457024 134512640 136285277 4291690208 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24456/statm: 2375 2152 234 433 0 1940 0 Current children cumulated CPU time (s) 24.63 Current children cumulated vsize (KiB) 12096 [startup+51.107 s] /proc/loadavg: 1.17 1.11 1.04 2/38 24458 /proc/meminfo: memFree=546044/1048576 swapFree=0/0 [pid=24447] ppid=24446 vsize=2596 CPUtime=2.28 /proc/24447/stat : 24447 (aspcud-1.5) S 24446 24447 19908 34817 19908 4202496 581 16872 0 0 0 0 222 6 16 0 1 0 62939864 2658304 299 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24447/statm: 649 299 251 194 0 36 0 [pid=24456] ppid=24447 vsize=9964 CPUtime=47.92 /proc/24456/stat : 24456 (clasp) R 24447 24447 19908 34817 19908 4202496 2630 0 0 0 4792 0 0 0 25 0 1 0 62939865 10203136 2280 1283457024 134512640 136285277 4291690208 18446744073709551615 134959497 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24456/statm: 2491 2280 234 433 0 2056 0 Current children cumulated CPU time (s) 50.2 Current children cumulated vsize (KiB) 12560 [startup+102.307 s] /proc/loadavg: 1.07 1.09 1.03 2/38 24458 /proc/meminfo: memFree=545052/1048576 swapFree=0/0 [pid=24447] ppid=24446 vsize=2596 CPUtime=2.28 /proc/24447/stat : 24447 (aspcud-1.5) S 24446 24447 19908 34817 19908 4202496 581 16872 0 0 0 0 222 6 16 0 1 0 62939864 2658304 299 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24447/statm: 649 299 251 194 0 36 0 [pid=24456] ppid=24447 vsize=10924 CPUtime=99.09 /proc/24456/stat : 24456 (clasp) R 24447 24447 19908 34817 19908 4202496 3028 0 0 0 9909 0 0 0 25 0 1 0 62939865 11186176 2520 1283457024 134512640 136285277 4291690208 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24456/statm: 2731 2520 234 433 0 2296 0 Current children cumulated CPU time (s) 101.37 Current children cumulated vsize (KiB) 13520 [startup+162.309 s] /proc/loadavg: 1.02 1.07 1.03 2/40 24461 /proc/meminfo: memFree=544160/1048576 swapFree=0/0 [pid=24447] ppid=24446 vsize=2596 CPUtime=2.28 /proc/24447/stat : 24447 (aspcud-1.5) S 24446 24447 19908 34817 19908 4202496 581 16872 0 0 0 0 222 6 16 0 1 0 62939864 2658304 299 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24447/statm: 649 299 251 194 0 36 0 [pid=24456] ppid=24447 vsize=11680 CPUtime=159.05 /proc/24456/stat : 24456 (clasp) R 24447 24447 19908 34817 19908 4202496 3373 0 0 0 15903 2 0 0 25 0 1 0 62939865 11960320 2695 1283457024 134512640 136285277 4291690208 18446744073709551615 134959543 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24456/statm: 2920 2695 234 433 0 2485 0 Current children cumulated CPU time (s) 161.33 Current children cumulated vsize (KiB) 14276 [startup+222.305 s] /proc/loadavg: 1.01 1.06 1.02 2/40 24467 /proc/meminfo: memFree=543168/1048576 swapFree=0/0 [pid=24447] ppid=24446 vsize=2596 CPUtime=2.28 /proc/24447/stat : 24447 (aspcud-1.5) S 24446 24447 19908 34817 19908 4202496 581 16872 0 0 0 0 222 6 16 0 1 0 62939864 2658304 299 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24447/statm: 649 299 251 194 0 36 0 [pid=24456] ppid=24447 vsize=12328 CPUtime=219.02 /proc/24456/stat : 24456 (clasp) R 24447 24447 19908 34817 19908 4202496 3725 0 0 0 21897 5 0 0 25 0 1 0 62939865 12623872 2866 1283457024 134512640 136285277 4291690208 18446744073709551615 134733752 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24456/statm: 3082 2866 234 433 0 2647 0 Current children cumulated CPU time (s) 221.3 Current children cumulated vsize (KiB) 14924 [startup+282.307 s] /proc/loadavg: 1.00 1.04 1.02 2/39 24469 /proc/meminfo: memFree=543184/1048576 swapFree=0/0 [pid=24447] ppid=24446 vsize=2596 CPUtime=2.28 /proc/24447/stat : 24447 (aspcud-1.5) S 24446 24447 19908 34817 19908 4202496 581 16872 0 0 0 0 222 6 16 0 1 0 62939864 2658304 299 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24447/statm: 649 299 251 194 0 36 0 [pid=24456] ppid=24447 vsize=12660 CPUtime=278.96 /proc/24456/stat : 24456 (clasp) R 24447 24447 19908 34817 19908 4202496 3875 0 0 0 27890 6 0 0 25 0 1 0 62939865 12963840 2949 1283457024 134512640 136285277 4291690208 18446744073709551615 134734770 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24456/statm: 3165 2949 234 433 0 2730 0 Current children cumulated CPU time (s) 281.24 Current children cumulated vsize (KiB) 15256 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+291.109 s] /proc/loadavg: 1.00 1.04 1.02 2/39 24469 /proc/meminfo: memFree=543184/1048576 swapFree=0/0 [pid=24447] ppid=24446 vsize=2596 CPUtime=2.28 /proc/24447/stat : 24447 (aspcud-1.5) S 24446 24447 19908 34817 19908 4202496 581 16872 0 0 0 0 222 6 16 0 1 0 62939864 2658304 299 1283457024 134512640 135304128 4289729824 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24447/statm: 649 299 251 194 0 36 0 [pid=24456] ppid=24447 vsize=12688 CPUtime=287.76 /proc/24456/stat : 24456 (clasp) R 24447 24447 19908 34817 19908 4202496 3892 0 0 0 28770 6 0 0 25 0 1 0 62939865 12992512 2956 1283457024 134512640 136285277 4291690208 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24456/statm: 3172 2956 234 433 0 2737 0 Current children cumulated CPU time (s) 290.04 Current children cumulated vsize (KiB) 15284 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): 291.13 CPU time (s): 290.074 CPU user time (s): 289.934 CPU system time (s): 0.140008 CPU usage (%): 99.6373 Max. virtual memory (cumulated for all children) (KiB): 56640 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.934 system time used= 0.140008 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 24896 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= 238 involuntary context switches= 3754 runsolver used 0 second user time and 0.012 second system time The end