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/rand283.cudf.user-upgrades.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/user-upgrades/rand283.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/rand283.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.12 1.03 1.01 2/37 22879 /proc/meminfo: memFree=720088/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=3024 CPUtime=0 /proc/22879/stat : 22879 (runsolver) D 22878 22879 19908 34817 19908 4202560 73 0 0 0 0 0 0 0 25 0 1 0 62207257 3096576 94 1283457024 134512640 134586868 4291306976 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/22879/statm: 756 94 62 19 0 55 0 [startup+0.196384 s] /proc/loadavg: 1.12 1.03 1.01 2/37 22879 /proc/meminfo: memFree=720088/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=2596 CPUtime=0 /proc/22879/stat : 22879 (aspcud-1.5) S 22878 22879 19908 34817 19908 4202496 581 1517 0 3 0 0 0 0 25 0 1 0 62207257 2658304 298 1283457024 134512640 135304128 4287462128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22879/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.204379 s] /proc/loadavg: 1.12 1.03 1.01 2/37 22879 /proc/meminfo: memFree=720088/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=2596 CPUtime=0 /proc/22879/stat : 22879 (aspcud-1.5) S 22878 22879 19908 34817 19908 4202496 581 1517 0 3 0 0 0 0 25 0 1 0 62207257 2658304 298 1283457024 134512640 135304128 4287462128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22879/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.304379 s] /proc/loadavg: 1.12 1.03 1.01 2/37 22879 /proc/meminfo: memFree=720088/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=2596 CPUtime=0 /proc/22879/stat : 22879 (aspcud-1.5) S 22878 22879 19908 34817 19908 4202496 581 1517 0 3 0 0 0 0 25 0 1 0 62207257 2658304 298 1283457024 134512640 135304128 4287462128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22879/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.704754 s] /proc/loadavg: 1.12 1.03 1.01 2/37 22879 /proc/meminfo: memFree=720088/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=2596 CPUtime=0 /proc/22879/stat : 22879 (aspcud-1.5) S 22878 22879 19908 34817 19908 4202496 581 1517 0 3 0 0 0 0 25 0 1 0 62207257 2658304 298 1283457024 134512640 135304128 4287462128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22879/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50446 s] /proc/loadavg: 1.12 1.03 1.01 2/41 22890 /proc/meminfo: memFree=689244/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=2596 CPUtime=0 /proc/22879/stat : 22879 (aspcud-1.5) S 22878 22879 19908 34817 19908 4202496 581 1517 0 3 0 0 0 0 25 0 1 0 62207257 2658304 298 1283457024 134512640 135304128 4287462128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22879/statm: 649 298 251 194 0 36 0 [pid=22888] ppid=22879 vsize=1932 CPUtime=0 /proc/22888/stat : 22888 (clasp) S 22879 22879 19908 34817 19908 4202496 274 0 18 0 0 0 0 0 23 0 1 0 62207260 1978368 160 1283457024 134512640 136285277 4288042208 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/22888/statm: 483 160 144 433 0 48 0 [pid=22889] ppid=22879 vsize=2584 CPUtime=0 /proc/22889/stat : 22889 (gringo) S 22879 22879 19908 34817 19908 4202496 381 0 23 0 0 0 0 0 23 0 1 0 62207260 2646016 272 1283457024 134512640 136933539 4288046304 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/22889/statm: 646 272 242 592 0 51 0 [pid=22890] ppid=22879 vsize=28112 CPUtime=1.01 /proc/22890/stat : 22890 (cudf2lp) R 22879 22879 19908 34817 19908 4202496 7837 0 15 0 100 1 0 0 25 0 1 0 62207260 28786688 6108 1283457024 134512640 135786343 4287066880 18446744073709551615 135199797 0 0 6 0 0 0 0 17 0 0 0 0 /proc/22890/statm: 7028 6108 128 311 0 6715 0 Current children cumulated CPU time (s) 1.01 Current children cumulated vsize (KiB) 35224 [startup+3.11429 s] /proc/loadavg: 1.11 1.03 1.01 2/41 22890 /proc/meminfo: memFree=660748/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=2596 CPUtime=2.24 /proc/22879/stat : 22879 (aspcud-1.5) R 22878 22879 19908 34817 19908 4202496 581 15477 0 18 0 0 216 8 19 0 1 0 62207257 2658304 298 1283457024 134512640 135304128 4287462128 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/22879/statm: 649 298 251 194 0 36 0 [pid=22888] ppid=22879 vsize=3660 CPUtime=0.22 /proc/22888/stat : 22888 (clasp) R 22879 22879 19908 34817 19908 4202496 816 0 21 0 22 0 0 0 18 0 1 0 62207260 3747840 705 1283457024 134512640 136285277 4288042208 18446744073709551615 134985090 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/22888/statm: 915 705 234 433 0 480 0 [pid=22889] ppid=22879 vsize=0 CPUtime=0.04 /proc/22889/stat : 22889 (gringo) Z 22879 22879 19908 34817 19908 4202508 957 0 23 0 4 0 0 0 18 0 1 0 62207260 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/22889/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.5 Current children cumulated vsize (KiB) 6256 [startup+6.30492 s] /proc/loadavg: 1.11 1.03 1.01 2/39 22890 /proc/meminfo: memFree=681336/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=2596 CPUtime=2.29 /proc/22879/stat : 22879 (aspcud-1.5) S 22878 22879 19908 34817 19908 4202496 581 16434 0 41 0 0 221 8 17 0 1 0 62207257 2658304 298 1283457024 134512640 135304128 4287462128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22879/statm: 649 298 251 194 0 36 0 [pid=22888] ppid=22879 vsize=4816 CPUtime=3.4 /proc/22888/stat : 22888 (clasp) R 22879 22879 19908 34817 19908 4202496 1126 0 21 0 340 0 0 0 25 0 1 0 62207260 4931584 999 1283457024 134512640 136285277 4288042208 18446744073709551615 134959560 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/22888/statm: 1204 999 234 433 0 769 0 Current children cumulated CPU time (s) 5.69 Current children cumulated vsize (KiB) 7412 [startup+12.7064 s] /proc/loadavg: 1.09 1.03 1.01 2/38 22890 /proc/meminfo: memFree=680980/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=2596 CPUtime=2.29 /proc/22879/stat : 22879 (aspcud-1.5) S 22878 22879 19908 34817 19908 4202496 581 16434 0 41 0 0 221 8 17 0 1 0 62207257 2658304 298 1283457024 134512640 135304128 4287462128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22879/statm: 649 298 251 194 0 36 0 [pid=22888] ppid=22879 vsize=5272 CPUtime=9.8 /proc/22888/stat : 22888 (clasp) R 22879 22879 19908 34817 19908 4202496 1248 0 21 0 980 0 0 0 25 0 1 0 62207260 5398528 1108 1283457024 134512640 136285277 4288042208 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/22888/statm: 1318 1108 234 433 0 883 0 Current children cumulated CPU time (s) 12.09 Current children cumulated vsize (KiB) 7868 [startup+25.5089 s] /proc/loadavg: 1.08 1.03 1.01 2/38 22890 /proc/meminfo: memFree=680360/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=2596 CPUtime=2.29 /proc/22879/stat : 22879 (aspcud-1.5) S 22878 22879 19908 34817 19908 4202496 581 16434 0 41 0 0 221 8 17 0 1 0 62207257 2658304 298 1283457024 134512640 135304128 4287462128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22879/statm: 649 298 251 194 0 36 0 [pid=22888] ppid=22879 vsize=5760 CPUtime=22.6 /proc/22888/stat : 22888 (clasp) R 22879 22879 19908 34817 19908 4202496 1428 0 21 0 2260 0 0 0 25 0 1 0 62207260 5898240 1234 1283457024 134512640 136285277 4288042208 18446744073709551615 134723327 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/22888/statm: 1440 1234 234 433 0 1005 0 Current children cumulated CPU time (s) 24.89 Current children cumulated vsize (KiB) 8356 [startup+51.1041 s] /proc/loadavg: 1.05 1.02 1.00 2/38 22890 /proc/meminfo: memFree=679988/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=2596 CPUtime=2.29 /proc/22879/stat : 22879 (aspcud-1.5) S 22878 22879 19908 34817 19908 4202496 581 16434 0 41 0 0 221 8 17 0 1 0 62207257 2658304 298 1283457024 134512640 135304128 4287462128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22879/statm: 649 298 251 194 0 36 0 [pid=22888] ppid=22879 vsize=6108 CPUtime=48.17 /proc/22888/stat : 22888 (clasp) R 22879 22879 19908 34817 19908 4202496 1574 0 21 0 4817 0 0 0 25 0 1 0 62207260 6254592 1318 1283457024 134512640 136285277 4288042208 18446744073709551615 134963355 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/22888/statm: 1527 1318 234 433 0 1092 0 Current children cumulated CPU time (s) 50.46 Current children cumulated vsize (KiB) 8704 [startup+102.307 s] /proc/loadavg: 1.02 1.02 1.00 2/38 22890 /proc/meminfo: memFree=679492/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=2596 CPUtime=2.29 /proc/22879/stat : 22879 (aspcud-1.5) S 22878 22879 19908 34817 19908 4202496 581 16434 0 41 0 0 221 8 17 0 1 0 62207257 2658304 298 1283457024 134512640 135304128 4287462128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22879/statm: 649 298 251 194 0 36 0 [pid=22888] ppid=22879 vsize=6596 CPUtime=99.33 /proc/22888/stat : 22888 (clasp) R 22879 22879 19908 34817 19908 4202496 1718 0 21 0 9933 0 0 0 25 0 1 0 62207260 6754304 1444 1283457024 134512640 136285277 4288042208 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/22888/statm: 1649 1444 234 433 0 1214 0 Current children cumulated CPU time (s) 101.62 Current children cumulated vsize (KiB) 9192 [startup+162.309 s] /proc/loadavg: 1.00 1.01 1.00 2/38 22890 /proc/meminfo: memFree=679120/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=2596 CPUtime=2.29 /proc/22879/stat : 22879 (aspcud-1.5) S 22878 22879 19908 34817 19908 4202496 581 16434 0 41 0 0 221 8 17 0 1 0 62207257 2658304 298 1283457024 134512640 135304128 4287462128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22879/statm: 649 298 251 194 0 36 0 [pid=22888] ppid=22879 vsize=6904 CPUtime=159.3 /proc/22888/stat : 22888 (clasp) R 22879 22879 19908 34817 19908 4202496 1816 0 21 0 15930 0 0 0 25 0 1 0 62207260 7069696 1502 1283457024 134512640 136285277 4288042208 18446744073709551615 134959788 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/22888/statm: 1726 1502 234 433 0 1291 0 Current children cumulated CPU time (s) 161.59 Current children cumulated vsize (KiB) 9500 [startup+222.303 s] /proc/loadavg: 1.00 1.01 1.00 2/38 22890 /proc/meminfo: memFree=678996/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=2596 CPUtime=2.29 /proc/22879/stat : 22879 (aspcud-1.5) S 22878 22879 19908 34817 19908 4202496 581 16434 0 41 0 0 221 8 17 0 1 0 62207257 2658304 298 1283457024 134512640 135304128 4287462128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22879/statm: 649 298 251 194 0 36 0 [pid=22888] ppid=22879 vsize=7076 CPUtime=219.26 /proc/22888/stat : 22888 (clasp) R 22879 22879 19908 34817 19908 4202496 1894 0 21 0 21926 0 0 0 25 0 1 0 62207260 7245824 1557 1283457024 134512640 136285277 4288042208 18446744073709551615 134955177 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/22888/statm: 1769 1557 234 433 0 1334 0 Current children cumulated CPU time (s) 221.55 Current children cumulated vsize (KiB) 9672 [startup+282.314 s] /proc/loadavg: 1.00 1.00 1.00 2/40 22895 /proc/meminfo: memFree=678724/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=2596 CPUtime=2.29 /proc/22879/stat : 22879 (aspcud-1.5) S 22878 22879 19908 34817 19908 4202496 581 16434 0 41 0 0 221 8 17 0 1 0 62207257 2658304 298 1283457024 134512640 135304128 4287462128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22879/statm: 649 298 251 194 0 36 0 [pid=22888] ppid=22879 vsize=7128 CPUtime=279.22 /proc/22888/stat : 22888 (clasp) R 22879 22879 19908 34817 19908 4202496 1937 0 21 0 27922 0 0 0 25 0 1 0 62207260 7299072 1577 1283457024 134512640 136285277 4288042208 18446744073709551615 134686280 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/22888/statm: 1782 1577 234 433 0 1347 0 Current children cumulated CPU time (s) 281.51 Current children cumulated vsize (KiB) 9724 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.816 s] /proc/loadavg: 1.00 1.00 1.00 2/40 22896 /proc/meminfo: memFree=678600/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=2596 CPUtime=2.29 /proc/22879/stat : 22879 (aspcud-1.5) S 22878 22879 19908 34817 19908 4202496 581 16434 0 41 0 0 221 8 17 0 1 0 62207257 2658304 298 1283457024 134512640 135304128 4287462128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22879/statm: 649 298 251 194 0 36 0 [pid=22888] ppid=22879 vsize=7324 CPUtime=287.72 /proc/22888/stat : 22888 (clasp) R 22879 22879 19908 34817 19908 4202496 1967 0 21 0 28772 0 0 0 25 0 1 0 62207260 7499776 1607 1283457024 134512640 136285277 4288042208 18446744073709551615 134733768 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/22888/statm: 1831 1607 234 433 0 1396 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 9920 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.816 s] /proc/loadavg: 1.00 1.00 1.00 2/40 22896 /proc/meminfo: memFree=678600/1048576 swapFree=0/0 [pid=22879] ppid=22878 vsize=2596 CPUtime=2.29 /proc/22879/stat : 22879 (aspcud-1.5) S 22878 22879 19908 34817 19908 4202496 581 16434 0 41 0 0 221 8 17 0 1 0 62207257 2658304 298 1283457024 134512640 135304128 4287462128 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/22879/statm: 649 298 251 194 0 36 0 [pid=22888] ppid=22879 vsize=7324 CPUtime=287.72 /proc/22888/stat : 22888 (clasp) R 22879 22879 19908 34817 19908 4202496 1967 0 21 0 28772 0 0 0 25 0 1 0 62207260 7499776 1607 1283457024 134512640 136285277 4288042208 18446744073709551615 134733768 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/22888/statm: 1831 1607 234 433 0 1396 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 9920 Child status: 0 Real time (s): 290.85 CPU time (s): 290.05 CPU user time (s): 289.942 CPU system time (s): 0.108006 CPU usage (%): 99.7251 Max. virtual memory (cumulated for all children) (KiB): 56780 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.942 system time used= 0.108006 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 22537 page faults= 63 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 265 involuntary context switches= 3714 runsolver used 0 second user time and 0 second system time The end