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/rand105.cudf.user-upgrades.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/user-upgrades/rand105.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/rand105.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: 0.99 1.02 0.86 3/41 20282 /proc/meminfo: memFree=861816/1048576 swapFree=0/0 [pid=20279] ppid=20278 vsize=2584 CPUtime=0 /proc/20279/stat : 20279 (aspcud-1.5) S 20278 20279 19908 34817 19908 4202496 372 0 0 0 0 0 0 0 25 0 1 0 60913330 2646016 279 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/20279/statm: 646 279 234 194 0 33 0 [pid=20280] ppid=20279 vsize=2584 CPUtime=0 /proc/20280/stat : 20280 (aspcud-1.5) S 20279 20279 19908 34817 19908 4202560 119 0 0 0 0 0 0 0 25 0 1 0 60913330 2646016 133 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/20280/statm: 646 133 87 194 0 33 0 [pid=20281] ppid=20280 vsize=2584 CPUtime=0 /proc/20281/stat : 20281 (aspcud-1.5) R 20280 20279 19908 34817 19908 4202560 128 0 0 0 0 0 0 0 25 0 1 0 60913330 2646016 150 1283457024 134512640 135304128 4291251856 18446744073709551615 4159600438 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/20281/statm: 646 150 104 194 0 33 0 [pid=20282] ppid=20281 vsize=0 CPUtime=0 /proc/20282/stat : 20282 (readlink) Z 20281 20279 19908 34817 19908 4194316 182 0 0 0 0 0 0 0 25 0 1 0 60913330 0 0 1283457024 0 0 0 0 0 0 0 0 0 18446744071564254338 0 0 17 0 0 0 0 /proc/20282/statm: 0 0 0 0 0 0 0 [startup+0.137594 s] /proc/loadavg: 0.99 1.02 0.86 3/41 20282 /proc/meminfo: memFree=861816/1048576 swapFree=0/0 [pid=20279] ppid=20278 vsize=2592 CPUtime=0 /proc/20279/stat : 20279 (aspcud-1.5) S 20278 20279 19908 34817 19908 4202496 575 1525 0 0 0 0 0 0 25 0 1 0 60913330 2654208 298 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20279/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.210644 s] /proc/loadavg: 0.99 1.02 0.86 3/41 20282 /proc/meminfo: memFree=861816/1048576 swapFree=0/0 [pid=20279] ppid=20278 vsize=2592 CPUtime=0 /proc/20279/stat : 20279 (aspcud-1.5) S 20278 20279 19908 34817 19908 4202496 575 1525 0 0 0 0 0 0 25 0 1 0 60913330 2654208 298 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20279/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.305599 s] /proc/loadavg: 0.99 1.02 0.86 3/41 20282 /proc/meminfo: memFree=861816/1048576 swapFree=0/0 [pid=20279] ppid=20278 vsize=2592 CPUtime=0 /proc/20279/stat : 20279 (aspcud-1.5) S 20278 20279 19908 34817 19908 4202496 575 1525 0 0 0 0 0 0 25 0 1 0 60913330 2654208 298 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20279/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.705632 s] /proc/loadavg: 0.99 1.02 0.86 3/41 20282 /proc/meminfo: memFree=861816/1048576 swapFree=0/0 [pid=20279] ppid=20278 vsize=2592 CPUtime=0 /proc/20279/stat : 20279 (aspcud-1.5) S 20278 20279 19908 34817 19908 4202496 575 1525 0 0 0 0 0 0 25 0 1 0 60913330 2654208 298 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20279/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.50568 s] /proc/loadavg: 0.99 1.02 0.86 2/42 20290 /proc/meminfo: memFree=831468/1048576 swapFree=0/0 [pid=20279] ppid=20278 vsize=2592 CPUtime=0 /proc/20279/stat : 20279 (aspcud-1.5) S 20278 20279 19908 34817 19908 4202496 575 1525 0 0 0 0 0 0 25 0 1 0 60913330 2654208 298 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20279/statm: 648 298 251 194 0 35 0 [pid=20288] ppid=20279 vsize=1924 CPUtime=0 /proc/20288/stat : 20288 (clasp) S 20279 20279 19908 34817 19908 4202496 291 0 0 0 0 0 0 0 25 0 1 0 60913331 1970176 159 1283457024 134512640 136285277 4294203712 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/20288/statm: 481 159 144 433 0 46 0 [pid=20289] ppid=20279 vsize=2580 CPUtime=0 /proc/20289/stat : 20289 (gringo) S 20279 20279 19908 34817 19908 4202496 403 0 0 0 0 0 0 0 25 0 1 0 60913331 2641920 271 1283457024 134512640 136933539 4291174096 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/20289/statm: 645 271 242 592 0 50 0 [pid=20290] ppid=20279 vsize=28116 CPUtime=1.2 /proc/20290/stat : 20290 (cudf2lp) R 20279 20279 19908 34817 19908 4202496 7981 0 0 0 114 6 0 0 25 0 1 0 60913331 28790784 6237 1283457024 134512640 135786343 4291274496 18446744073709551615 134614137 0 0 6 0 0 0 0 17 0 0 0 0 /proc/20290/statm: 7029 6237 128 311 0 6716 0 Current children cumulated CPU time (s) 1.2 Current children cumulated vsize (KiB) 35212 [startup+3.10735 s] /proc/loadavg: 0.99 1.02 0.86 2/42 20291 /proc/meminfo: memFree=802412/1048576 swapFree=0/0 [pid=20279] ppid=20278 vsize=2592 CPUtime=2.19 /proc/20279/stat : 20279 (aspcud-1.5) R 20278 20279 19908 34817 19908 4202496 575 15500 0 0 0 0 208 11 19 0 1 0 60913330 2654208 298 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/20279/statm: 648 298 251 194 0 35 0 [pid=20288] ppid=20279 vsize=4448 CPUtime=0.38 /proc/20288/stat : 20288 (clasp) R 20279 20279 19908 34817 19908 4202496 1021 0 0 0 38 0 0 0 18 0 1 0 60913331 4554752 884 1283457024 134512640 136285277 4294203712 18446744073709551615 134733720 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20288/statm: 1112 884 233 433 0 677 0 [pid=20289] ppid=20279 vsize=0 CPUtime=0.08 /proc/20289/stat : 20289 (gringo) Z 20279 20279 19908 34817 19908 4202508 1245 0 0 0 8 0 0 0 18 0 1 0 60913331 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/20289/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.65 Current children cumulated vsize (KiB) 7040 [startup+6.30805 s] /proc/loadavg: 0.99 1.02 0.86 2/40 20291 /proc/meminfo: memFree=826748/1048576 swapFree=0/0 [pid=20279] ppid=20278 vsize=2592 CPUtime=2.28 /proc/20279/stat : 20279 (aspcud-1.5) S 20278 20279 19908 34817 19908 4202496 575 16745 0 0 0 0 217 11 17 0 1 0 60913330 2654208 298 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20279/statm: 648 298 251 194 0 35 0 [pid=20288] ppid=20279 vsize=6692 CPUtime=3.56 /proc/20288/stat : 20288 (clasp) R 20279 20279 19908 34817 19908 4202496 1576 0 0 0 356 0 0 0 25 0 1 0 60913331 6852608 1439 1283457024 134512640 136285277 4294203712 18446744073709551615 134615170 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20288/statm: 1673 1439 233 433 0 1238 0 Current children cumulated CPU time (s) 5.84 Current children cumulated vsize (KiB) 9284 [startup+12.7094 s] /proc/loadavg: 0.99 1.02 0.86 2/40 20292 /proc/meminfo: memFree=825756/1048576 swapFree=0/0 [pid=20279] ppid=20278 vsize=2592 CPUtime=2.28 /proc/20279/stat : 20279 (aspcud-1.5) S 20278 20279 19908 34817 19908 4202496 575 16745 0 0 0 0 217 11 17 0 1 0 60913330 2654208 298 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20279/statm: 648 298 251 194 0 35 0 [pid=20288] ppid=20279 vsize=7456 CPUtime=9.96 /proc/20288/stat : 20288 (clasp) R 20279 20279 19908 34817 19908 4202496 1783 0 0 0 996 0 0 0 25 0 1 0 60913331 7634944 1646 1283457024 134512640 136285277 4294203712 18446744073709551615 135668787 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20288/statm: 1864 1646 234 433 0 1429 0 Current children cumulated CPU time (s) 12.24 Current children cumulated vsize (KiB) 10048 [startup+25.5136 s] /proc/loadavg: 0.99 1.02 0.86 2/40 20293 /proc/meminfo: memFree=825508/1048576 swapFree=0/0 [pid=20279] ppid=20278 vsize=2592 CPUtime=2.28 /proc/20279/stat : 20279 (aspcud-1.5) S 20278 20279 19908 34817 19908 4202496 575 16745 0 0 0 0 217 11 17 0 1 0 60913330 2654208 298 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20279/statm: 648 298 251 194 0 35 0 [pid=20288] ppid=20279 vsize=7720 CPUtime=22.75 /proc/20288/stat : 20288 (clasp) R 20279 20279 19908 34817 19908 4202496 1835 0 0 0 2275 0 0 0 25 0 1 0 60913331 7905280 1698 1283457024 134512640 136285277 4294203712 18446744073709551615 134615068 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20288/statm: 1930 1698 234 433 0 1495 0 Current children cumulated CPU time (s) 25.03 Current children cumulated vsize (KiB) 10312 [startup+51.1098 s] /proc/loadavg: 0.99 1.01 0.87 2/40 20295 /proc/meminfo: memFree=824516/1048576 swapFree=0/0 [pid=20279] ppid=20278 vsize=2592 CPUtime=2.28 /proc/20279/stat : 20279 (aspcud-1.5) S 20278 20279 19908 34817 19908 4202496 575 16745 0 0 0 0 217 11 17 0 1 0 60913330 2654208 298 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20279/statm: 648 298 251 194 0 35 0 [pid=20288] ppid=20279 vsize=8676 CPUtime=48.33 /proc/20288/stat : 20288 (clasp) R 20279 20279 19908 34817 19908 4202496 2150 0 0 0 4833 0 0 0 25 0 1 0 60913331 8884224 1956 1283457024 134512640 136285277 4294203712 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20288/statm: 2169 1956 234 433 0 1734 0 Current children cumulated CPU time (s) 50.61 Current children cumulated vsize (KiB) 11268 [startup+102.311 s] /proc/loadavg: 0.99 1.01 0.87 2/39 20295 /proc/meminfo: memFree=823540/1048576 swapFree=0/0 [pid=20279] ppid=20278 vsize=2592 CPUtime=2.28 /proc/20279/stat : 20279 (aspcud-1.5) S 20278 20279 19908 34817 19908 4202496 575 16745 0 0 0 0 217 11 17 0 1 0 60913330 2654208 298 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20279/statm: 648 298 251 194 0 35 0 [pid=20288] ppid=20279 vsize=9884 CPUtime=99.49 /proc/20288/stat : 20288 (clasp) R 20279 20279 19908 34817 19908 4202496 2522 0 0 0 9949 0 0 0 25 0 1 0 60913331 10121216 2238 1283457024 134512640 136285277 4294203712 18446744073709551615 134967011 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20288/statm: 2471 2238 234 433 0 2036 0 Current children cumulated CPU time (s) 101.77 Current children cumulated vsize (KiB) 12476 [startup+162.305 s] /proc/loadavg: 0.99 1.00 0.88 2/38 20296 /proc/meminfo: memFree=823052/1048576 swapFree=0/0 [pid=20279] ppid=20278 vsize=2592 CPUtime=2.28 /proc/20279/stat : 20279 (aspcud-1.5) S 20278 20279 19908 34817 19908 4202496 575 16745 0 0 0 0 217 11 17 0 1 0 60913330 2654208 298 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20279/statm: 648 298 251 194 0 35 0 [pid=20288] ppid=20279 vsize=10220 CPUtime=159.4 /proc/20288/stat : 20288 (clasp) R 20279 20279 19908 34817 19908 4202496 2866 0 0 0 15940 0 0 0 25 0 1 0 60913331 10465280 2335 1283457024 134512640 136285277 4294203712 18446744073709551615 134959571 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20288/statm: 2555 2335 234 433 0 2120 0 Current children cumulated CPU time (s) 161.68 Current children cumulated vsize (KiB) 12812 [startup+222.306 s] /proc/loadavg: 0.99 1.00 0.88 2/38 20296 /proc/meminfo: memFree=822556/1048576 swapFree=0/0 [pid=20279] ppid=20278 vsize=2592 CPUtime=2.28 /proc/20279/stat : 20279 (aspcud-1.5) S 20278 20279 19908 34817 19908 4202496 575 16745 0 0 0 0 217 11 17 0 1 0 60913330 2654208 298 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20279/statm: 648 298 251 194 0 35 0 [pid=20288] ppid=20279 vsize=10540 CPUtime=219.34 /proc/20288/stat : 20288 (clasp) R 20279 20279 19908 34817 19908 4202496 3034 0 0 0 21934 0 0 0 25 0 1 0 60913331 10792960 2423 1283457024 134512640 136285277 4294203712 18446744073709551615 134985131 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20288/statm: 2635 2423 234 433 0 2200 0 Current children cumulated CPU time (s) 221.62 Current children cumulated vsize (KiB) 13132 [startup+282.31 s] /proc/loadavg: 0.99 1.00 0.89 2/38 20296 /proc/meminfo: memFree=821936/1048576 swapFree=0/0 [pid=20279] ppid=20278 vsize=2592 CPUtime=2.28 /proc/20279/stat : 20279 (aspcud-1.5) S 20278 20279 19908 34817 19908 4202496 575 16745 0 0 0 0 217 11 17 0 1 0 60913330 2654208 298 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20279/statm: 648 298 251 194 0 35 0 [pid=20288] ppid=20279 vsize=11112 CPUtime=279.32 /proc/20288/stat : 20288 (clasp) R 20279 20279 19908 34817 19908 4202496 3999 0 0 0 27932 0 0 0 25 0 1 0 60913331 11378688 2566 1283457024 134512640 136285277 4294203712 18446744073709551615 134615133 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20288/statm: 2778 2566 234 433 0 2343 0 Current children cumulated CPU time (s) 281.6 Current children cumulated vsize (KiB) 13704 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.712 s] /proc/loadavg: 0.99 1.00 0.89 2/38 20296 /proc/meminfo: memFree=821812/1048576 swapFree=0/0 [pid=20279] ppid=20278 vsize=2592 CPUtime=2.28 /proc/20279/stat : 20279 (aspcud-1.5) S 20278 20279 19908 34817 19908 4202496 575 16745 0 0 0 0 217 11 17 0 1 0 60913330 2654208 298 1283457024 134512640 135304128 4291251856 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20279/statm: 648 298 251 194 0 35 0 [pid=20288] ppid=20279 vsize=11112 CPUtime=287.72 /proc/20288/stat : 20288 (clasp) R 20279 20279 19908 34817 19908 4202496 4156 0 0 0 28772 0 0 0 25 0 1 0 60913331 11378688 2566 1283457024 134512640 136285277 4294203712 18446744073709551615 134963447 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20288/statm: 2778 2566 234 433 0 2343 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 13704 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.733 CPU time (s): 290.034 CPU user time (s): 289.898 CPU system time (s): 0.136008 CPU usage (%): 99.7598 Max. virtual memory (cumulated for all children) (KiB): 55580 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.898 system time used= 0.136008 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 25014 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= 3713 runsolver used 0 second user time and 0.004 second system time The end