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/rand97.cudf.user-upgrades.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/user-upgrades/rand97.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/rand97.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.04 1.02 1.00 1/35 30220 /proc/meminfo: memFree=810772/1048576 swapFree=0/0 [pid=30220] ppid=30219 vsize=3020 CPUtime=0 /proc/30220/stat : 30220 (runsolver) D 30219 30220 19908 34817 19908 4202560 72 0 0 0 0 0 0 0 25 0 1 0 65883763 3092480 94 1283457024 134512640 134586868 4293402592 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/30220/statm: 755 94 62 19 0 54 0 [startup+0.1231 s] /proc/loadavg: 1.04 1.02 1.00 1/35 30220 /proc/meminfo: memFree=810772/1048576 swapFree=0/0 [pid=30220] ppid=30219 vsize=2600 CPUtime=0 /proc/30220/stat : 30220 (aspcud-1.5) S 30219 30220 19908 34817 19908 4202496 580 1517 0 3 0 0 0 0 25 0 1 0 65883763 2662400 299 1283457024 134512640 135304128 4287562512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30220/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.207082 s] /proc/loadavg: 1.04 1.02 1.00 1/35 30220 /proc/meminfo: memFree=810772/1048576 swapFree=0/0 [pid=30220] ppid=30219 vsize=2600 CPUtime=0 /proc/30220/stat : 30220 (aspcud-1.5) S 30219 30220 19908 34817 19908 4202496 580 1517 0 3 0 0 0 0 25 0 1 0 65883763 2662400 299 1283457024 134512640 135304128 4287562512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30220/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.30713 s] /proc/loadavg: 1.04 1.02 1.00 1/35 30220 /proc/meminfo: memFree=810772/1048576 swapFree=0/0 [pid=30220] ppid=30219 vsize=2600 CPUtime=0 /proc/30220/stat : 30220 (aspcud-1.5) S 30219 30220 19908 34817 19908 4202496 580 1517 0 3 0 0 0 0 25 0 1 0 65883763 2662400 299 1283457024 134512640 135304128 4287562512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30220/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.707127 s] /proc/loadavg: 1.04 1.02 1.00 1/35 30220 /proc/meminfo: memFree=810772/1048576 swapFree=0/0 [pid=30220] ppid=30219 vsize=2600 CPUtime=0 /proc/30220/stat : 30220 (aspcud-1.5) S 30219 30220 19908 34817 19908 4202496 580 1517 0 3 0 0 0 0 25 0 1 0 65883763 2662400 299 1283457024 134512640 135304128 4287562512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30220/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+1.50718 s] /proc/loadavg: 1.04 1.02 1.00 2/39 30231 /proc/meminfo: memFree=780656/1048576 swapFree=0/0 [pid=30220] ppid=30219 vsize=2600 CPUtime=0 /proc/30220/stat : 30220 (aspcud-1.5) S 30219 30220 19908 34817 19908 4202496 580 1517 0 3 0 0 0 0 25 0 1 0 65883763 2662400 299 1283457024 134512640 135304128 4287562512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30220/statm: 650 299 251 194 0 37 0 [pid=30229] ppid=30220 vsize=1924 CPUtime=0 /proc/30229/stat : 30229 (clasp) S 30220 30220 19908 34817 19908 4202496 273 0 19 0 0 0 0 0 23 0 1 0 65883767 1970176 159 1283457024 134512640 136285277 4291459168 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/30229/statm: 481 159 144 433 0 46 0 [pid=30230] ppid=30220 vsize=2588 CPUtime=0 /proc/30230/stat : 30230 (gringo) S 30220 30220 19908 34817 19908 4202496 383 0 22 0 0 0 0 0 22 0 1 0 65883767 2650112 272 1283457024 134512640 136933539 4289918368 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/30230/statm: 647 272 242 592 0 52 0 [pid=30231] ppid=30220 vsize=28032 CPUtime=1.04 /proc/30231/stat : 30231 (cudf2lp) R 30220 30220 19908 34817 19908 4202496 6806 0 15 0 104 0 0 0 25 0 1 0 65883767 28704768 5781 1283457024 134512640 135786343 4291773552 18446744073709551615 134620438 0 0 6 0 0 0 0 17 0 0 0 0 /proc/30231/statm: 7008 5781 128 311 0 6695 0 Current children cumulated CPU time (s) 1.04 Current children cumulated vsize (KiB) 35144 [startup+3.10852 s] /proc/loadavg: 1.04 1.02 1.00 2/39 30231 /proc/meminfo: memFree=753684/1048576 swapFree=0/0 [pid=30220] ppid=30219 vsize=2600 CPUtime=2.3 /proc/30220/stat : 30220 (aspcud-1.5) R 30219 30220 19908 34817 19908 4202496 580 15478 0 18 0 0 227 3 19 0 1 0 65883763 2662400 299 1283457024 134512640 135304128 4287562512 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/30220/statm: 650 299 251 194 0 37 0 [pid=30229] ppid=30220 vsize=4852 CPUtime=0.04 /proc/30229/stat : 30229 (clasp) R 30220 30220 19908 34817 19908 4202496 1112 0 22 0 4 0 0 0 18 0 1 0 65883767 4968448 993 1283457024 134512640 136285277 4291459168 18446744073709551615 134733720 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30229/statm: 1213 993 234 433 0 778 0 [pid=30230] ppid=30220 vsize=0 CPUtime=0.09 /proc/30230/stat : 30230 (gringo) Z 30220 30220 19908 34817 19908 4202508 1345 0 22 0 7 2 0 0 18 0 1 0 65883767 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/30230/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.43 Current children cumulated vsize (KiB) 7452 heavy processes: [startup+6.30892 s] /proc/loadavg: 1.11 1.03 1.01 2/37 30231 /proc/meminfo: memFree=769920/1048576 swapFree=0/0 [pid=30220] ppid=30219 vsize=2600 CPUtime=2.39 /proc/30220/stat : 30220 (aspcud-1.5) S 30219 30220 19908 34817 19908 4202496 580 16823 0 40 0 0 234 5 17 0 1 0 65883763 2662400 299 1283457024 134512640 135304128 4287562512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30220/statm: 650 299 251 194 0 37 0 [pid=30229] ppid=30220 vsize=7320 CPUtime=3.24 /proc/30229/stat : 30229 (clasp) R 30220 30220 19908 34817 19908 4202496 1732 0 22 0 324 0 0 0 25 0 1 0 65883767 7495680 1613 1283457024 134512640 136285277 4291459168 18446744073709551615 134966761 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30229/statm: 1830 1613 234 433 0 1395 0 Current children cumulated CPU time (s) 5.63 Current children cumulated vsize (KiB) 9920 [startup+12.7106 s] /proc/loadavg: 1.10 1.03 1.01 2/37 30232 /proc/meminfo: memFree=769184/1048576 swapFree=0/0 [pid=30220] ppid=30219 vsize=2600 CPUtime=2.39 /proc/30220/stat : 30220 (aspcud-1.5) S 30219 30220 19908 34817 19908 4202496 580 16823 0 40 0 0 234 5 17 0 1 0 65883763 2662400 299 1283457024 134512640 135304128 4287562512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30220/statm: 650 299 251 194 0 37 0 [pid=30229] ppid=30220 vsize=7764 CPUtime=9.65 /proc/30229/stat : 30229 (clasp) R 30220 30220 19908 34817 19908 4202496 1843 0 22 0 965 0 0 0 25 0 1 0 65883767 7950336 1724 1283457024 134512640 136285277 4291459168 18446744073709551615 134650174 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30229/statm: 1941 1724 234 433 0 1506 0 Current children cumulated CPU time (s) 12.04 Current children cumulated vsize (KiB) 10364 [startup+25.5131 s] /proc/loadavg: 1.08 1.03 1.00 2/37 30233 /proc/meminfo: memFree=768192/1048576 swapFree=0/0 [pid=30220] ppid=30219 vsize=2600 CPUtime=2.39 /proc/30220/stat : 30220 (aspcud-1.5) S 30219 30220 19908 34817 19908 4202496 580 16823 0 40 0 0 234 5 17 0 1 0 65883763 2662400 299 1283457024 134512640 135304128 4287562512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30220/statm: 650 299 251 194 0 37 0 [pid=30229] ppid=30220 vsize=8692 CPUtime=22.43 /proc/30229/stat : 30229 (clasp) R 30220 30220 19908 34817 19908 4202496 2057 0 22 0 2243 0 0 0 25 0 1 0 65883767 8900608 1937 1283457024 134512640 136285277 4291459168 18446744073709551615 134930666 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30229/statm: 2173 1937 234 433 0 1738 0 Current children cumulated CPU time (s) 24.82 Current children cumulated vsize (KiB) 11292 [startup+51.1086 s] /proc/loadavg: 1.05 1.03 1.00 2/37 30236 /proc/meminfo: memFree=767572/1048576 swapFree=0/0 [pid=30220] ppid=30219 vsize=2600 CPUtime=2.39 /proc/30220/stat : 30220 (aspcud-1.5) S 30219 30220 19908 34817 19908 4202496 580 16823 0 40 0 0 234 5 17 0 1 0 65883763 2662400 299 1283457024 134512640 135304128 4287562512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30220/statm: 650 299 251 194 0 37 0 [pid=30229] ppid=30220 vsize=9332 CPUtime=48.01 /proc/30229/stat : 30229 (clasp) R 30220 30220 19908 34817 19908 4202496 2333 0 22 0 4801 0 0 0 25 0 1 0 65883767 9555968 2104 1283457024 134512640 136285277 4291459168 18446744073709551615 134963393 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30229/statm: 2333 2104 234 433 0 1898 0 Current children cumulated CPU time (s) 50.4 Current children cumulated vsize (KiB) 11932 [startup+102.31 s] /proc/loadavg: 1.02 1.02 1.00 2/36 30239 /proc/meminfo: memFree=766596/1048576 swapFree=0/0 [pid=30220] ppid=30219 vsize=2600 CPUtime=2.39 /proc/30220/stat : 30220 (aspcud-1.5) S 30219 30220 19908 34817 19908 4202496 580 16823 0 40 0 0 234 5 17 0 1 0 65883763 2662400 299 1283457024 134512640 135304128 4287562512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30220/statm: 650 299 251 194 0 37 0 [pid=30229] ppid=30220 vsize=10260 CPUtime=99.19 /proc/30229/stat : 30229 (clasp) R 30220 30220 19908 34817 19908 4202496 3591 0 22 0 9917 2 0 0 25 0 1 0 65883767 10506240 2355 1283457024 134512640 136285277 4291459168 18446744073709551615 134986742 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30229/statm: 2565 2355 234 433 0 2130 0 Current children cumulated CPU time (s) 101.58 Current children cumulated vsize (KiB) 12860 [startup+162.312 s] /proc/loadavg: 1.01 1.02 1.00 2/35 30239 /proc/meminfo: memFree=765860/1048576 swapFree=0/0 [pid=30220] ppid=30219 vsize=2600 CPUtime=2.39 /proc/30220/stat : 30220 (aspcud-1.5) S 30219 30220 19908 34817 19908 4202496 580 16823 0 40 0 0 234 5 17 0 1 0 65883763 2662400 299 1283457024 134512640 135304128 4287562512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30220/statm: 650 299 251 194 0 37 0 [pid=30229] ppid=30220 vsize=10928 CPUtime=159.16 /proc/30229/stat : 30229 (clasp) R 30220 30220 19908 34817 19908 4202496 3917 0 22 0 15914 2 0 0 25 0 1 0 65883767 11190272 2526 1283457024 134512640 136285277 4291459168 18446744073709551615 134734770 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30229/statm: 2732 2526 234 433 0 2297 0 Current children cumulated CPU time (s) 161.55 Current children cumulated vsize (KiB) 13528 [startup+222.305 s] /proc/loadavg: 1.00 1.01 1.00 2/35 30239 /proc/meminfo: memFree=765612/1048576 swapFree=0/0 [pid=30220] ppid=30219 vsize=2600 CPUtime=2.39 /proc/30220/stat : 30220 (aspcud-1.5) S 30219 30220 19908 34817 19908 4202496 580 16823 0 40 0 0 234 5 17 0 1 0 65883763 2662400 299 1283457024 134512640 135304128 4287562512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30220/statm: 650 299 251 194 0 37 0 [pid=30229] ppid=30220 vsize=11104 CPUtime=219.1 /proc/30229/stat : 30229 (clasp) R 30220 30220 19908 34817 19908 4202496 4093 0 22 0 21908 2 0 0 25 0 1 0 65883767 11370496 2559 1283457024 134512640 136285277 4291459168 18446744073709551615 134733809 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30229/statm: 2776 2559 234 433 0 2341 0 Current children cumulated CPU time (s) 221.49 Current children cumulated vsize (KiB) 13704 [startup+282.31 s] /proc/loadavg: 1.00 1.00 1.00 2/35 30239 /proc/meminfo: memFree=765116/1048576 swapFree=0/0 [pid=30220] ppid=30219 vsize=2600 CPUtime=2.39 /proc/30220/stat : 30220 (aspcud-1.5) S 30219 30220 19908 34817 19908 4202496 580 16823 0 40 0 0 234 5 17 0 1 0 65883763 2662400 299 1283457024 134512640 135304128 4287562512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30220/statm: 650 299 251 194 0 37 0 [pid=30229] ppid=30220 vsize=11544 CPUtime=279.06 /proc/30229/stat : 30229 (clasp) R 30220 30220 19908 34817 19908 4202496 4997 0 22 0 27902 4 0 0 25 0 1 0 65883767 11821056 2678 1283457024 134512640 136285277 4291459168 18446744073709551615 134967003 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30229/statm: 2886 2678 234 433 0 2451 0 Current children cumulated CPU time (s) 281.45 Current children cumulated vsize (KiB) 14144 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.912 s] /proc/loadavg: 1.00 1.00 1.00 2/35 30239 /proc/meminfo: memFree=765116/1048576 swapFree=0/0 [pid=30220] ppid=30219 vsize=2600 CPUtime=2.39 /proc/30220/stat : 30220 (aspcud-1.5) S 30219 30220 19908 34817 19908 4202496 580 16823 0 40 0 0 234 5 17 0 1 0 65883763 2662400 299 1283457024 134512640 135304128 4287562512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30220/statm: 650 299 251 194 0 37 0 [pid=30229] ppid=30220 vsize=11544 CPUtime=287.66 /proc/30229/stat : 30229 (clasp) R 30220 30220 19908 34817 19908 4202496 4997 0 22 0 28762 4 0 0 25 0 1 0 65883767 11821056 2678 1283457024 134512640 136285277 4291459168 18446744073709551615 134733784 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30229/statm: 2886 2678 234 433 0 2451 0 Current children cumulated CPU time (s) 290.05 Current children cumulated vsize (KiB) 14144 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.958 CPU time (s): 290.082 CPU user time (s): 289.978 CPU system time (s): 0.104006 CPU usage (%): 99.699 Max. virtual memory (cumulated for all children) (KiB): 55596 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.978 system time used= 0.104006 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 25942 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= 312 involuntary context switches= 3751 runsolver used 0 second user time and 0 second system time The end