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/rand740.cudf.user-upgrades.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/user-upgrades/rand740.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/rand740.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.20 1.11 1.03 4/38 28085 /proc/meminfo: memFree=404020/1048576 swapFree=0/0 [pid=28082] ppid=28081 vsize=2584 CPUtime=0 /proc/28082/stat : 28082 (aspcud-1.5) S 28081 28082 19908 34817 19908 4202496 372 0 0 0 0 0 0 0 25 0 1 0 64689243 2646016 279 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/28082/statm: 646 279 234 194 0 33 0 [pid=28083] ppid=28082 vsize=2584 CPUtime=0 /proc/28083/stat : 28083 (aspcud-1.5) S 28082 28082 19908 34817 19908 4202560 118 0 0 0 0 0 0 0 25 0 1 0 64689243 2646016 133 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/28083/statm: 646 133 87 194 0 33 0 [pid=28084] ppid=28083 vsize=2584 CPUtime=0.01 /proc/28084/stat : 28084 (aspcud-1.5) R 28083 28082 19908 34817 19908 4202560 126 0 0 0 0 1 0 0 25 0 1 0 64689243 2646016 150 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/28084/statm: 646 150 104 194 0 33 0 [pid=28085] ppid=28084 vsize=2584 CPUtime=0 /proc/28085/stat : 28085 (aspcud-1.5) R 28084 28082 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 64689243 2646016 46 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/28085/statm: 646 46 0 194 0 33 0 [startup+0.138697 s] /proc/loadavg: 1.20 1.11 1.03 4/38 28085 /proc/meminfo: memFree=404020/1048576 swapFree=0/0 [pid=28082] ppid=28081 vsize=2592 CPUtime=0.01 /proc/28082/stat : 28082 (aspcud-1.5) S 28081 28082 19908 34817 19908 4202496 580 1521 0 0 0 0 0 1 25 0 1 0 64689243 2654208 298 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28082/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.206703 s] /proc/loadavg: 1.20 1.11 1.03 4/38 28085 /proc/meminfo: memFree=404020/1048576 swapFree=0/0 [pid=28082] ppid=28081 vsize=2592 CPUtime=0.01 /proc/28082/stat : 28082 (aspcud-1.5) S 28081 28082 19908 34817 19908 4202496 580 1521 0 0 0 0 0 1 25 0 1 0 64689243 2654208 298 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28082/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.306715 s] /proc/loadavg: 1.20 1.11 1.03 4/38 28085 /proc/meminfo: memFree=404020/1048576 swapFree=0/0 [pid=28082] ppid=28081 vsize=2592 CPUtime=0.01 /proc/28082/stat : 28082 (aspcud-1.5) S 28081 28082 19908 34817 19908 4202496 580 1521 0 0 0 0 0 1 25 0 1 0 64689243 2654208 298 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28082/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.702738 s] /proc/loadavg: 1.20 1.11 1.03 4/38 28085 /proc/meminfo: memFree=404020/1048576 swapFree=0/0 [pid=28082] ppid=28081 vsize=2592 CPUtime=0.01 /proc/28082/stat : 28082 (aspcud-1.5) S 28081 28082 19908 34817 19908 4202496 580 1521 0 0 0 0 0 1 25 0 1 0 64689243 2654208 298 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28082/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+1.51111 s] /proc/loadavg: 1.20 1.11 1.03 2/38 28093 /proc/meminfo: memFree=374932/1048576 swapFree=0/0 [pid=28082] ppid=28081 vsize=2592 CPUtime=0.01 /proc/28082/stat : 28082 (aspcud-1.5) S 28081 28082 19908 34817 19908 4202496 580 1521 0 0 0 0 0 1 25 0 1 0 64689243 2654208 298 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28082/statm: 648 298 251 194 0 35 0 [pid=28091] ppid=28082 vsize=1928 CPUtime=0 /proc/28091/stat : 28091 (clasp) S 28082 28082 19908 34817 19908 4202496 291 0 0 0 0 0 0 0 25 0 1 0 64689244 1974272 159 1283457024 134512640 136285277 4293736656 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/28091/statm: 482 159 144 433 0 47 0 [pid=28092] ppid=28082 vsize=2588 CPUtime=0 /proc/28092/stat : 28092 (gringo) S 28082 28082 19908 34817 19908 4202496 404 0 0 0 0 0 0 0 25 0 1 0 64689244 2650112 272 1283457024 134512640 136933539 4289355040 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/28092/statm: 647 272 242 592 0 52 0 [pid=28093] ppid=28082 vsize=28116 CPUtime=1.13 /proc/28093/stat : 28093 (cudf2lp) R 28082 28082 19908 34817 19908 4202496 7945 0 0 0 106 7 0 0 25 0 1 0 64689244 28790784 6201 1283457024 134512640 135786343 4288164864 18446744073709551615 134627309 0 0 6 0 0 0 0 17 0 0 0 0 /proc/28093/statm: 7029 6201 128 311 0 6716 0 Current children cumulated CPU time (s) 1.14 Current children cumulated vsize (KiB) 35224 [startup+3.11001 s] /proc/loadavg: 1.20 1.11 1.03 2/38 28093 /proc/meminfo: memFree=347708/1048576 swapFree=0/0 [pid=28082] ppid=28081 vsize=2592 CPUtime=2.16 /proc/28082/stat : 28082 (aspcud-1.5) R 28081 28082 19908 34817 19908 4202496 580 15496 0 0 0 0 206 10 19 0 1 0 64689243 2654208 298 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/28082/statm: 648 298 251 194 0 35 0 [pid=28091] ppid=28082 vsize=4340 CPUtime=0.29 /proc/28091/stat : 28091 (clasp) R 28082 28082 19908 34817 19908 4202496 996 0 0 0 28 1 0 0 18 0 1 0 64689244 4444160 855 1283457024 134512640 136285277 4293736656 18446744073709551615 134649414 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28091/statm: 1085 855 233 433 0 650 0 [pid=28092] ppid=28082 vsize=0 CPUtime=0.05 /proc/28092/stat : 28092 (gringo) Z 28082 28082 19908 34817 19908 4202508 1246 0 0 0 5 0 0 0 18 0 1 0 64689244 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/28092/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.5 Current children cumulated vsize (KiB) 6932 [startup+6.31059 s] /proc/loadavg: 1.27 1.13 1.04 2/36 28093 /proc/meminfo: memFree=370604/1048576 swapFree=0/0 [pid=28082] ppid=28081 vsize=2592 CPUtime=2.22 /proc/28082/stat : 28082 (aspcud-1.5) S 28081 28082 19908 34817 19908 4202496 580 16742 0 0 0 0 212 10 17 0 1 0 64689243 2654208 298 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28082/statm: 648 298 251 194 0 35 0 [pid=28091] ppid=28082 vsize=5928 CPUtime=3.49 /proc/28091/stat : 28091 (clasp) R 28082 28082 19908 34817 19908 4202496 1420 0 0 0 348 1 0 0 25 0 1 0 64689244 6070272 1277 1283457024 134512640 136285277 4293736656 18446744073709551615 134735727 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28091/statm: 1482 1277 234 433 0 1047 0 Current children cumulated CPU time (s) 5.71 Current children cumulated vsize (KiB) 8520 [startup+12.7119 s] /proc/loadavg: 1.25 1.12 1.03 2/36 28093 /proc/meminfo: memFree=369124/1048576 swapFree=0/0 [pid=28082] ppid=28081 vsize=2592 CPUtime=2.22 /proc/28082/stat : 28082 (aspcud-1.5) S 28081 28082 19908 34817 19908 4202496 580 16742 0 0 0 0 212 10 17 0 1 0 64689243 2654208 298 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28082/statm: 648 298 251 194 0 35 0 [pid=28091] ppid=28082 vsize=6564 CPUtime=9.9 /proc/28091/stat : 28091 (clasp) R 28082 28082 19908 34817 19908 4202496 1556 0 0 0 988 2 0 0 25 0 1 0 64689244 6721536 1413 1283457024 134512640 136285277 4293736656 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28091/statm: 1641 1413 234 433 0 1206 0 Current children cumulated CPU time (s) 12.12 Current children cumulated vsize (KiB) 9156 [startup+25.5045 s] /proc/loadavg: 1.19 1.12 1.03 2/36 28093 /proc/meminfo: memFree=369124/1048576 swapFree=0/0 [pid=28082] ppid=28081 vsize=2592 CPUtime=2.22 /proc/28082/stat : 28082 (aspcud-1.5) S 28081 28082 19908 34817 19908 4202496 580 16742 0 0 0 0 212 10 17 0 1 0 64689243 2654208 298 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28082/statm: 648 298 251 194 0 35 0 [pid=28091] ppid=28082 vsize=6564 CPUtime=22.68 /proc/28091/stat : 28091 (clasp) R 28082 28082 19908 34817 19908 4202496 1565 0 0 0 2266 2 0 0 25 0 1 0 64689244 6721536 1422 1283457024 134512640 136285277 4293736656 18446744073709551615 134959792 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28091/statm: 1641 1422 234 433 0 1206 0 Current children cumulated CPU time (s) 24.9 Current children cumulated vsize (KiB) 9156 [startup+51.1089 s] /proc/loadavg: 1.12 1.11 1.03 2/36 28093 /proc/meminfo: memFree=368380/1048576 swapFree=0/0 [pid=28082] ppid=28081 vsize=2592 CPUtime=2.22 /proc/28082/stat : 28082 (aspcud-1.5) S 28081 28082 19908 34817 19908 4202496 580 16742 0 0 0 0 212 10 17 0 1 0 64689243 2654208 298 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28082/statm: 648 298 251 194 0 35 0 [pid=28091] ppid=28082 vsize=7200 CPUtime=48.27 /proc/28091/stat : 28091 (clasp) R 28082 28082 19908 34817 19908 4202496 1731 0 0 0 4825 2 0 0 25 0 1 0 64689244 7372800 1588 1283457024 134512640 136285277 4293736656 18446744073709551615 134955202 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28091/statm: 1800 1588 234 433 0 1365 0 Current children cumulated CPU time (s) 50.49 Current children cumulated vsize (KiB) 9792 [startup+102.31 s] /proc/loadavg: 1.05 1.09 1.03 2/35 28093 /proc/meminfo: memFree=368016/1048576 swapFree=0/0 [pid=28082] ppid=28081 vsize=2592 CPUtime=2.22 /proc/28082/stat : 28082 (aspcud-1.5) S 28081 28082 19908 34817 19908 4202496 580 16742 0 0 0 0 212 10 17 0 1 0 64689243 2654208 298 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28082/statm: 648 298 251 194 0 35 0 [pid=28091] ppid=28082 vsize=7664 CPUtime=99.47 /proc/28091/stat : 28091 (clasp) R 28082 28082 19908 34817 19908 4202496 1854 0 0 0 9945 2 0 0 25 0 1 0 64689244 7847936 1701 1283457024 134512640 136285277 4293736656 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28091/statm: 1916 1701 234 433 0 1481 0 Current children cumulated CPU time (s) 101.69 Current children cumulated vsize (KiB) 10256 [startup+162.313 s] /proc/loadavg: 1.02 1.07 1.02 2/35 28093 /proc/meminfo: memFree=367768/1048576 swapFree=0/0 [pid=28082] ppid=28081 vsize=2592 CPUtime=2.22 /proc/28082/stat : 28082 (aspcud-1.5) S 28081 28082 19908 34817 19908 4202496 580 16742 0 0 0 0 212 10 17 0 1 0 64689243 2654208 298 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28082/statm: 648 298 251 194 0 35 0 [pid=28091] ppid=28082 vsize=7920 CPUtime=159.46 /proc/28091/stat : 28091 (clasp) R 28082 28082 19908 34817 19908 4202496 1908 0 0 0 15944 2 0 0 25 0 1 0 64689244 8110080 1740 1283457024 134512640 136285277 4293736656 18446744073709551615 134667519 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28091/statm: 1980 1740 234 433 0 1545 0 Current children cumulated CPU time (s) 161.68 Current children cumulated vsize (KiB) 10512 [startup+222.312 s] /proc/loadavg: 1.00 1.05 1.01 2/35 28093 /proc/meminfo: memFree=367520/1048576 swapFree=0/0 [pid=28082] ppid=28081 vsize=2592 CPUtime=2.22 /proc/28082/stat : 28082 (aspcud-1.5) S 28081 28082 19908 34817 19908 4202496 580 16742 0 0 0 0 212 10 17 0 1 0 64689243 2654208 298 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28082/statm: 648 298 251 194 0 35 0 [pid=28091] ppid=28082 vsize=8096 CPUtime=219.4 /proc/28091/stat : 28091 (clasp) R 28082 28082 19908 34817 19908 4202496 1981 0 0 0 21936 4 0 0 25 0 1 0 64689244 8290304 1813 1283457024 134512640 136285277 4293736656 18446744073709551615 134964936 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28091/statm: 2024 1813 234 433 0 1589 0 Current children cumulated CPU time (s) 221.62 Current children cumulated vsize (KiB) 10688 [startup+282.313 s] /proc/loadavg: 1.00 1.04 1.01 2/35 28093 /proc/meminfo: memFree=366404/1048576 swapFree=0/0 [pid=28082] ppid=28081 vsize=2592 CPUtime=2.22 /proc/28082/stat : 28082 (aspcud-1.5) S 28081 28082 19908 34817 19908 4202496 580 16742 0 0 0 0 212 10 17 0 1 0 64689243 2654208 298 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28082/statm: 648 298 251 194 0 35 0 [pid=28091] ppid=28082 vsize=9196 CPUtime=279.38 /proc/28091/stat : 28091 (clasp) R 28082 28082 19908 34817 19908 4202496 2287 0 0 0 27934 4 0 0 25 0 1 0 64689244 9416704 2078 1283457024 134512640 136285277 4293736656 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28091/statm: 2299 2078 234 433 0 1864 0 Current children cumulated CPU time (s) 281.6 Current children cumulated vsize (KiB) 11788 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.705 s] /proc/loadavg: 1.00 1.04 1.01 2/35 28093 /proc/meminfo: memFree=366404/1048576 swapFree=0/0 [pid=28082] ppid=28081 vsize=2592 CPUtime=2.22 /proc/28082/stat : 28082 (aspcud-1.5) S 28081 28082 19908 34817 19908 4202496 580 16742 0 0 0 0 212 10 17 0 1 0 64689243 2654208 298 1283457024 134512640 135304128 4287740720 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/28082/statm: 648 298 251 194 0 35 0 [pid=28091] ppid=28082 vsize=9196 CPUtime=287.78 /proc/28091/stat : 28091 (clasp) R 28082 28082 19908 34817 19908 4202496 2287 0 0 0 28774 4 0 0 25 0 1 0 64689244 9416704 2078 1283457024 134512640 136285277 4293736656 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/28091/statm: 2299 2078 234 433 0 1864 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 11788 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.726 CPU time (s): 290.034 CPU user time (s): 289.866 CPU system time (s): 0.16801 CPU usage (%): 99.7621 Max. virtual memory (cumulated for all children) (KiB): 55592 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.866 system time used= 0.16801 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 23154 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= 219 involuntary context switches= 3672 runsolver used 0 second user time and 0 second system time The end