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/201108300820/aspuncud-user-1.0/rand283.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand283.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/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.00 1.03 1.00 2/35 5171 /proc/meminfo: memFree=931868/1048576 swapFree=0/0 [pid=5171] ppid=5170 vsize=3020 CPUtime=0 /proc/5171/stat : 5171 (runsolver) D 5170 5171 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 52492123 3092480 93 1283457024 134512640 134586868 4287257072 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/5171/statm: 755 93 62 19 0 54 0 [startup+0.133125 s] /proc/loadavg: 1.00 1.03 1.00 2/35 5171 /proc/meminfo: memFree=931868/1048576 swapFree=0/0 [pid=5171] ppid=5170 vsize=2596 CPUtime=0 /proc/5171/stat : 5171 (aspuncud-user-1) S 5170 5171 2160 34817 2160 4202496 573 1514 0 3 0 0 0 0 25 0 1 0 52492123 2658304 298 1283457024 134512640 135304128 4291155552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5171/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.205128 s] /proc/loadavg: 1.00 1.03 1.00 2/35 5171 /proc/meminfo: memFree=931868/1048576 swapFree=0/0 [pid=5171] ppid=5170 vsize=2596 CPUtime=0 /proc/5171/stat : 5171 (aspuncud-user-1) S 5170 5171 2160 34817 2160 4202496 573 1514 0 3 0 0 0 0 25 0 1 0 52492123 2658304 298 1283457024 134512640 135304128 4291155552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5171/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.30512 s] /proc/loadavg: 1.00 1.03 1.00 2/35 5171 /proc/meminfo: memFree=931868/1048576 swapFree=0/0 [pid=5171] ppid=5170 vsize=2596 CPUtime=0 /proc/5171/stat : 5171 (aspuncud-user-1) S 5170 5171 2160 34817 2160 4202496 573 1514 0 3 0 0 0 0 25 0 1 0 52492123 2658304 298 1283457024 134512640 135304128 4291155552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5171/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.702186 s] /proc/loadavg: 1.00 1.03 1.00 2/35 5171 /proc/meminfo: memFree=931868/1048576 swapFree=0/0 [pid=5171] ppid=5170 vsize=2596 CPUtime=0 /proc/5171/stat : 5171 (aspuncud-user-1) S 5170 5171 2160 34817 2160 4202496 573 1514 0 3 0 0 0 0 25 0 1 0 52492123 2658304 298 1283457024 134512640 135304128 4291155552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5171/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50239 s] /proc/loadavg: 1.00 1.03 1.00 2/39 5182 /proc/meminfo: memFree=913008/1048576 swapFree=0/0 [pid=5171] ppid=5170 vsize=2596 CPUtime=0 /proc/5171/stat : 5171 (aspuncud-user-1) S 5170 5171 2160 34817 2160 4202496 573 1514 0 3 0 0 0 0 25 0 1 0 52492123 2658304 298 1283457024 134512640 135304128 4291155552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5171/statm: 649 298 251 194 0 36 0 [pid=5180] ppid=5171 vsize=3444 CPUtime=0 /proc/5180/stat : 5180 (unclasp) S 5171 5171 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 25 0 1 0 52492128 3526656 271 1283457024 134512640 135121179 4293962960 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/5180/statm: 861 271 240 149 0 52 0 [pid=5181] ppid=5171 vsize=2692 CPUtime=0 /proc/5181/stat : 5181 (gringo) S 5171 5171 2160 34817 2160 4202496 386 0 23 0 0 0 0 0 24 0 1 0 52492128 2756608 281 1283457024 134512640 137056543 4291760016 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/5181/statm: 673 281 252 622 0 48 0 [pid=5182] ppid=5171 vsize=28112 CPUtime=1.27 /proc/5182/stat : 5182 (cudf2lp) R 5171 5171 2160 34817 2160 4202496 7929 0 15 0 125 2 0 0 25 0 1 0 52492128 28786688 6205 1283457024 134512640 135786343 4292439248 18446744073709551615 134850409 0 0 6 0 0 0 0 17 0 0 0 0 /proc/5182/statm: 7028 6205 128 311 0 6715 0 Current children cumulated CPU time (s) 1.27 Current children cumulated vsize (KiB) 36844 [startup+3.10277 s] /proc/loadavg: 1.00 1.03 1.00 2/39 5182 /proc/meminfo: memFree=896516/1048576 swapFree=0/0 [pid=5171] ppid=5170 vsize=2596 CPUtime=0 /proc/5171/stat : 5171 (aspuncud-user-1) S 5170 5171 2160 34817 2160 4202496 573 1514 0 3 0 0 0 0 25 0 1 0 52492123 2658304 298 1283457024 134512640 135304128 4291155552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5171/statm: 649 298 251 194 0 36 0 [pid=5180] ppid=5171 vsize=11820 CPUtime=0.03 /proc/5180/stat : 5180 (unclasp) S 5171 5171 2160 34817 2160 4202496 2830 0 6 0 3 0 0 0 18 0 1 0 52492128 12103680 2314 1283457024 134512640 135121179 4293962960 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/5180/statm: 2955 2314 275 149 0 2146 0 [pid=5181] ppid=5171 vsize=16240 CPUtime=0.41 /proc/5181/stat : 5181 (gringo) R 5171 5171 2160 34817 2160 4202496 4343 0 23 0 41 0 0 0 18 0 1 0 52492128 16629760 2789 1283457024 134512640 137056543 4291760016 18446744073709551615 136285215 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5181/statm: 4060 2789 253 622 0 3435 0 [pid=5182] ppid=5171 vsize=44564 CPUtime=2.44 /proc/5182/stat : 5182 (cudf2lp) R 5171 5171 2160 34817 2160 4202496 13951 0 15 0 238 6 0 0 25 0 1 0 52492128 45633536 10934 1283457024 134512640 135786343 4292439248 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/5182/statm: 11141 10934 139 311 0 10828 0 Current children cumulated CPU time (s) 2.88 Current children cumulated vsize (KiB) 75220 [startup+6.30338 s] /proc/loadavg: 1.00 1.03 1.00 3/39 5182 /proc/meminfo: memFree=796644/1048576 swapFree=0/0 [pid=5171] ppid=5170 vsize=2596 CPUtime=3.12 /proc/5171/stat : 5171 (aspuncud-user-1) S 5170 5171 2160 34817 2160 4202496 573 15468 0 18 0 0 302 10 18 0 1 0 52492123 2658304 298 1283457024 134512640 135304128 4291155552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5171/statm: 649 298 251 194 0 36 0 [pid=5180] ppid=5171 vsize=53140 CPUtime=0.24 /proc/5180/stat : 5180 (unclasp) R 5171 5171 2160 34817 2160 4202496 15266 0 6 0 17 7 0 0 18 0 1 0 52492128 54415360 12454 1283457024 134512640 135121179 4293962960 18446744073709551615 4157670115 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5180/statm: 13285 12454 276 149 0 12476 0 [pid=5181] ppid=5171 vsize=74992 CPUtime=2.7 /proc/5181/stat : 5181 (gringo) R 5171 5171 2160 34817 2160 4202496 25182 0 23 0 258 12 0 0 18 0 1 0 52492128 76791808 15034 1283457024 134512640 137056543 4291760016 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5181/statm: 18748 15034 268 622 0 18123 0 Current children cumulated CPU time (s) 6.06 Current children cumulated vsize (KiB) 130728 [startup+12.7089 s] /proc/loadavg: 1.07 1.04 1.00 2/37 5183 /proc/meminfo: memFree=808580/1048576 swapFree=0/0 [pid=5171] ppid=5170 vsize=2596 CPUtime=8.07 /proc/5171/stat : 5171 (aspuncud-user-1) S 5170 5171 2160 34817 2160 4202496 573 63514 0 41 0 0 771 36 18 0 1 0 52492123 2658304 298 1283457024 134512640 135304128 4291155552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5171/statm: 649 298 251 194 0 36 0 [pid=5180] ppid=5171 vsize=128668 CPUtime=4.38 /proc/5180/stat : 5180 (unclasp) R 5171 5171 2160 34817 2160 4202496 92691 0 7 0 400 38 0 0 25 0 1 0 52492128 131756032 29886 1283457024 134512640 135121179 4293962960 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5180/statm: 32167 29886 321 149 0 31358 0 Current children cumulated CPU time (s) 12.45 Current children cumulated vsize (KiB) 131264 [startup+25.5029 s] /proc/loadavg: 1.06 1.04 1.00 2/36 5183 /proc/meminfo: memFree=808596/1048576 swapFree=0/0 [pid=5171] ppid=5170 vsize=2596 CPUtime=8.07 /proc/5171/stat : 5171 (aspuncud-user-1) S 5170 5171 2160 34817 2160 4202496 573 63514 0 41 0 0 771 36 18 0 1 0 52492123 2658304 298 1283457024 134512640 135304128 4291155552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5171/statm: 649 298 251 194 0 36 0 [pid=5180] ppid=5171 vsize=128668 CPUtime=17.17 /proc/5180/stat : 5180 (unclasp) R 5171 5171 2160 34817 2160 4202496 342353 0 7 0 1574 143 0 0 25 0 1 0 52492128 131756032 29897 1283457024 134512640 135121179 4293962960 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5180/statm: 32167 29897 321 149 0 31358 0 Current children cumulated CPU time (s) 25.24 Current children cumulated vsize (KiB) 131264 [startup+51.1047 s] /proc/loadavg: 1.04 1.03 1.00 2/36 5183 /proc/meminfo: memFree=808472/1048576 swapFree=0/0 [pid=5171] ppid=5170 vsize=2596 CPUtime=8.07 /proc/5171/stat : 5171 (aspuncud-user-1) S 5170 5171 2160 34817 2160 4202496 573 63514 0 41 0 0 771 36 18 0 1 0 52492123 2658304 298 1283457024 134512640 135304128 4291155552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5171/statm: 649 298 251 194 0 36 0 [pid=5180] ppid=5171 vsize=128672 CPUtime=42.75 /proc/5180/stat : 5180 (unclasp) R 5171 5171 2160 34817 2160 4202496 829922 0 7 0 3925 350 0 0 25 0 1 0 52492128 131760128 29908 1283457024 134512640 135121179 4293962960 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5180/statm: 32168 29908 321 149 0 31359 0 Current children cumulated CPU time (s) 50.82 Current children cumulated vsize (KiB) 131268 [startup+102.312 s] /proc/loadavg: 1.01 1.03 1.00 2/35 5183 /proc/meminfo: memFree=808232/1048576 swapFree=0/0 [pid=5171] ppid=5170 vsize=2596 CPUtime=8.07 /proc/5171/stat : 5171 (aspuncud-user-1) S 5170 5171 2160 34817 2160 4202496 573 63514 0 41 0 0 771 36 18 0 1 0 52492123 2658304 298 1283457024 134512640 135304128 4291155552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5171/statm: 649 298 251 194 0 36 0 [pid=5180] ppid=5171 vsize=128892 CPUtime=93.91 /proc/5180/stat : 5180 (unclasp) R 5171 5171 2160 34817 2160 4202496 1794411 0 7 0 8645 746 0 0 25 0 1 0 52492128 131985408 29950 1283457024 134512640 135121179 4293962960 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5180/statm: 32223 29950 321 149 0 31414 0 Current children cumulated CPU time (s) 101.98 Current children cumulated vsize (KiB) 131488 [startup+162.313 s] /proc/loadavg: 1.00 1.02 1.00 2/35 5183 /proc/meminfo: memFree=807984/1048576 swapFree=0/0 [pid=5171] ppid=5170 vsize=2596 CPUtime=8.07 /proc/5171/stat : 5171 (aspuncud-user-1) S 5170 5171 2160 34817 2160 4202496 573 63514 0 41 0 0 771 36 18 0 1 0 52492123 2658304 298 1283457024 134512640 135304128 4291155552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5171/statm: 649 298 251 194 0 36 0 [pid=5180] ppid=5171 vsize=129256 CPUtime=153.89 /proc/5180/stat : 5180 (unclasp) R 5171 5171 2160 34817 2160 4202496 2895743 0 7 0 14205 1184 0 0 25 0 1 0 52492128 132358144 29970 1283457024 134512640 135121179 4293962960 18446744073709551615 134734375 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5180/statm: 32314 29970 321 149 0 31505 0 Current children cumulated CPU time (s) 161.96 Current children cumulated vsize (KiB) 131852 [startup+222.303 s] /proc/loadavg: 1.00 1.01 1.00 2/35 5183 /proc/meminfo: memFree=807860/1048576 swapFree=0/0 [pid=5171] ppid=5170 vsize=2596 CPUtime=8.07 /proc/5171/stat : 5171 (aspuncud-user-1) S 5170 5171 2160 34817 2160 4202496 573 63514 0 41 0 0 771 36 18 0 1 0 52492123 2658304 298 1283457024 134512640 135304128 4291155552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5171/statm: 649 298 251 194 0 36 0 [pid=5180] ppid=5171 vsize=129268 CPUtime=213.83 /proc/5180/stat : 5180 (unclasp) R 5171 5171 2160 34817 2160 4202496 3982792 0 7 0 19763 1620 0 0 25 0 1 0 52492128 132370432 29990 1283457024 134512640 135121179 4293962960 18446744073709551615 134734317 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5180/statm: 32317 29990 321 149 0 31508 0 Current children cumulated CPU time (s) 221.9 Current children cumulated vsize (KiB) 131864 [startup+282.313 s] /proc/loadavg: 1.00 1.01 1.00 2/35 5183 /proc/meminfo: memFree=806620/1048576 swapFree=0/0 [pid=5171] ppid=5170 vsize=2596 CPUtime=8.07 /proc/5171/stat : 5171 (aspuncud-user-1) S 5170 5171 2160 34817 2160 4202496 573 63514 0 41 0 0 771 36 18 0 1 0 52492123 2658304 298 1283457024 134512640 135304128 4291155552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5171/statm: 649 298 251 194 0 36 0 [pid=5180] ppid=5171 vsize=129272 CPUtime=273.78 /proc/5180/stat : 5180 (unclasp) R 5171 5171 2160 34817 2160 4202496 5058362 0 7 0 25279 2099 0 0 25 0 1 0 52492128 132374528 30006 1283457024 134512640 135121179 4293962960 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5180/statm: 32318 30006 321 149 0 31509 0 Current children cumulated CPU time (s) 281.85 Current children cumulated vsize (KiB) 131868 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.505 s] /proc/loadavg: 1.00 1.01 1.00 2/35 5183 /proc/meminfo: memFree=805008/1048576 swapFree=0/0 [pid=5171] ppid=5170 vsize=2596 CPUtime=8.07 /proc/5171/stat : 5171 (aspuncud-user-1) S 5170 5171 2160 34817 2160 4202496 573 63514 0 41 0 0 771 36 18 0 1 0 52492123 2658304 298 1283457024 134512640 135304128 4291155552 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5171/statm: 649 298 251 194 0 36 0 [pid=5180] ppid=5171 vsize=132360 CPUtime=281.96 /proc/5180/stat : 5180 (unclasp) R 5171 5171 2160 34817 2160 4202496 5205242 0 7 0 26039 2157 0 0 25 0 1 0 52492128 135536640 30781 1283457024 134512640 135121179 4293962960 18446744073709551615 134981273 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5180/statm: 33090 30781 321 149 0 32281 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 134956 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.542 CPU time (s): 290.066 CPU user time (s): 268.109 CPU system time (s): 21.9574 CPU usage (%): 99.8363 Max. virtual memory (cumulated for all children) (KiB): 249692 getrusage(RUSAGE_CHILDREN,...) data: user time used= 268.109 system time used= 21.9574 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 5271744 page faults= 50 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 9353 involuntary context switches= 11087 runsolver used 0 second user time and 0.004 second system time The end