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/rand924.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand924.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand924.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.04 1.00 1/35 11896 /proc/meminfo: memFree=932100/1048576 swapFree=0/0 [pid=11896] ppid=11895 vsize=3020 CPUtime=0 /proc/11896/stat : 11896 (runsolver) D 11895 11896 2160 34817 2160 4202560 73 0 0 0 0 0 0 0 25 0 1 0 55974105 3092480 94 1283457024 134512640 134586868 4290975088 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/11896/statm: 755 94 62 19 0 54 0 [startup+0.18155 s] /proc/loadavg: 1.00 1.04 1.00 1/35 11896 /proc/meminfo: memFree=932100/1048576 swapFree=0/0 [pid=11896] ppid=11895 vsize=2596 CPUtime=0 /proc/11896/stat : 11896 (aspuncud-user-1) S 11895 11896 2160 34817 2160 4202496 574 1519 0 3 0 0 0 0 25 0 1 0 55974105 2658304 298 1283457024 134512640 135304128 4289574112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11896/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.205549 s] /proc/loadavg: 1.00 1.04 1.00 1/35 11896 /proc/meminfo: memFree=932100/1048576 swapFree=0/0 [pid=11896] ppid=11895 vsize=2596 CPUtime=0 /proc/11896/stat : 11896 (aspuncud-user-1) S 11895 11896 2160 34817 2160 4202496 574 1519 0 3 0 0 0 0 25 0 1 0 55974105 2658304 298 1283457024 134512640 135304128 4289574112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11896/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.306152 s] /proc/loadavg: 1.00 1.04 1.00 1/35 11896 /proc/meminfo: memFree=932100/1048576 swapFree=0/0 [pid=11896] ppid=11895 vsize=2596 CPUtime=0 /proc/11896/stat : 11896 (aspuncud-user-1) S 11895 11896 2160 34817 2160 4202496 574 1519 0 3 0 0 0 0 25 0 1 0 55974105 2658304 298 1283457024 134512640 135304128 4289574112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11896/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.706234 s] /proc/loadavg: 1.00 1.04 1.00 1/35 11896 /proc/meminfo: memFree=932100/1048576 swapFree=0/0 [pid=11896] ppid=11895 vsize=2596 CPUtime=0 /proc/11896/stat : 11896 (aspuncud-user-1) S 11895 11896 2160 34817 2160 4202496 574 1519 0 3 0 0 0 0 25 0 1 0 55974105 2658304 298 1283457024 134512640 135304128 4289574112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11896/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50641 s] /proc/loadavg: 1.00 1.04 1.00 2/39 11907 /proc/meminfo: memFree=913148/1048576 swapFree=0/0 [pid=11896] ppid=11895 vsize=2596 CPUtime=0 /proc/11896/stat : 11896 (aspuncud-user-1) S 11895 11896 2160 34817 2160 4202496 574 1519 0 3 0 0 0 0 25 0 1 0 55974105 2658304 298 1283457024 134512640 135304128 4289574112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11896/statm: 649 298 251 194 0 36 0 [pid=11905] ppid=11896 vsize=3444 CPUtime=0 /proc/11905/stat : 11905 (unclasp) S 11896 11896 2160 34817 2160 4202496 403 0 5 0 0 0 0 0 25 0 1 0 55974110 3526656 272 1283457024 134512640 135121179 4291139680 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/11905/statm: 861 272 240 149 0 52 0 [pid=11906] ppid=11896 vsize=2688 CPUtime=0 /proc/11906/stat : 11906 (gringo) S 11896 11896 2160 34817 2160 4202496 385 0 23 0 0 0 0 0 24 0 1 0 55974110 2752512 280 1283457024 134512640 137056543 4293570208 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/11906/statm: 672 280 252 622 0 47 0 [pid=11907] ppid=11896 vsize=28112 CPUtime=1.28 /proc/11907/stat : 11907 (cudf2lp) R 11896 11896 2160 34817 2160 4202496 7922 0 15 0 127 1 0 0 25 0 1 0 55974110 28786688 6198 1283457024 134512640 135786343 4291139680 18446744073709551615 135199382 0 0 6 0 0 0 0 17 0 0 0 0 /proc/11907/statm: 7028 6198 128 311 0 6715 0 Current children cumulated CPU time (s) 1.28 Current children cumulated vsize (KiB) 36840 [startup+3.10675 s] /proc/loadavg: 1.00 1.04 1.00 2/39 11907 /proc/meminfo: memFree=899384/1048576 swapFree=0/0 [pid=11896] ppid=11895 vsize=2596 CPUtime=0 /proc/11896/stat : 11896 (aspuncud-user-1) S 11895 11896 2160 34817 2160 4202496 574 1519 0 3 0 0 0 0 25 0 1 0 55974105 2658304 298 1283457024 134512640 135304128 4289574112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11896/statm: 649 298 251 194 0 36 0 [pid=11905] ppid=11896 vsize=11192 CPUtime=0.02 /proc/11905/stat : 11905 (unclasp) R 11896 11896 2160 34817 2160 4202496 2588 0 6 0 2 0 0 0 18 0 1 0 55974110 11460608 2254 1283457024 134512640 135121179 4291139680 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/11905/statm: 2798 2254 275 149 0 1989 0 [pid=11906] ppid=11896 vsize=16236 CPUtime=0.45 /proc/11906/stat : 11906 (gringo) R 11896 11896 2160 34817 2160 4202496 4307 0 23 0 39 6 0 0 18 0 1 0 55974110 16625664 2753 1283457024 134512640 137056543 4293570208 18446744073709551615 136301696 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/11906/statm: 4059 2753 253 622 0 3434 0 [pid=11907] ppid=11896 vsize=44564 CPUtime=2.4 /proc/11907/stat : 11907 (cudf2lp) R 11896 11896 2160 34817 2160 4202496 13952 0 15 0 236 4 0 0 25 0 1 0 55974110 45633536 10935 1283457024 134512640 135786343 4291139680 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/11907/statm: 11141 10935 139 311 0 10828 0 Current children cumulated CPU time (s) 2.87 Current children cumulated vsize (KiB) 74588 [startup+6.30745 s] /proc/loadavg: 1.00 1.04 1.00 3/39 11907 /proc/meminfo: memFree=797580/1048576 swapFree=0/0 [pid=11896] ppid=11895 vsize=2596 CPUtime=2.97 /proc/11896/stat : 11896 (aspuncud-user-1) S 11895 11896 2160 34817 2160 4202496 574 15474 0 18 0 0 292 5 18 0 1 0 55974105 2658304 298 1283457024 134512640 135304128 4289574112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11896/statm: 649 298 251 194 0 36 0 [pid=11905] ppid=11896 vsize=52872 CPUtime=0.21 /proc/11905/stat : 11905 (unclasp) R 11896 11896 2160 34817 2160 4202496 15160 0 6 0 21 0 0 0 18 0 1 0 55974110 54140928 12348 1283457024 134512640 135121179 4291139680 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/11905/statm: 13218 12348 276 149 0 12409 0 [pid=11906] ppid=11896 vsize=74476 CPUtime=2.88 /proc/11906/stat : 11906 (gringo) R 11896 11896 2160 34817 2160 4202496 25050 0 23 0 271 17 0 0 18 0 1 0 55974110 76263424 14902 1283457024 134512640 137056543 4293570208 18446744073709551615 136268477 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/11906/statm: 18619 14902 268 622 0 17994 0 Current children cumulated CPU time (s) 6.06 Current children cumulated vsize (KiB) 129944 [startup+12.7115 s] /proc/loadavg: 1.00 1.04 1.00 2/37 11908 /proc/meminfo: memFree=808532/1048576 swapFree=0/0 [pid=11896] ppid=11895 vsize=2596 CPUtime=7.95 /proc/11896/stat : 11896 (aspuncud-user-1) S 11895 11896 2160 34817 2160 4202496 574 63522 0 41 0 0 765 30 18 0 1 0 55974105 2658304 298 1283457024 134512640 135304128 4289574112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11896/statm: 649 298 251 194 0 36 0 [pid=11905] ppid=11896 vsize=128524 CPUtime=4.51 /proc/11905/stat : 11905 (unclasp) R 11896 11896 2160 34817 2160 4202496 88714 0 7 0 425 26 0 0 25 0 1 0 55974110 131608576 29918 1283457024 134512640 135121179 4291139680 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/11905/statm: 32131 29918 321 149 0 31322 0 Current children cumulated CPU time (s) 12.46 Current children cumulated vsize (KiB) 131120 [startup+25.5075 s] /proc/loadavg: 1.00 1.03 1.00 2/37 11909 /proc/meminfo: memFree=806052/1048576 swapFree=0/0 [pid=11896] ppid=11895 vsize=2596 CPUtime=7.95 /proc/11896/stat : 11896 (aspuncud-user-1) S 11895 11896 2160 34817 2160 4202496 574 63522 0 41 0 0 765 30 18 0 1 0 55974105 2658304 298 1283457024 134512640 135304128 4289574112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11896/statm: 649 298 251 194 0 36 0 [pid=11905] ppid=11896 vsize=133620 CPUtime=17.27 /proc/11905/stat : 11905 (unclasp) R 11896 11896 2160 34817 2160 4202496 321002 0 7 0 1601 126 0 0 25 0 1 0 55974110 136826880 30792 1283457024 134512640 135121179 4291139680 18446744073709551615 4157590294 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/11905/statm: 33405 30792 321 149 0 32596 0 Current children cumulated CPU time (s) 25.22 Current children cumulated vsize (KiB) 136216 [startup+51.1065 s] /proc/loadavg: 1.00 1.03 1.00 2/37 11912 /proc/meminfo: memFree=805928/1048576 swapFree=0/0 [pid=11896] ppid=11895 vsize=2596 CPUtime=7.95 /proc/11896/stat : 11896 (aspuncud-user-1) S 11895 11896 2160 34817 2160 4202496 574 63522 0 41 0 0 765 30 18 0 1 0 55974105 2658304 298 1283457024 134512640 135304128 4289574112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11896/statm: 649 298 251 194 0 36 0 [pid=11905] ppid=11896 vsize=128528 CPUtime=42.85 /proc/11905/stat : 11905 (unclasp) R 11896 11896 2160 34817 2160 4202496 778148 0 7 0 3977 308 0 0 25 0 1 0 55974110 131612672 29934 1283457024 134512640 135121179 4291139680 18446744073709551615 4159021591 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/11905/statm: 32132 29934 321 149 0 31323 0 Current children cumulated CPU time (s) 50.8 Current children cumulated vsize (KiB) 131124 [startup+102.305 s] /proc/loadavg: 1.00 1.02 1.00 2/36 11916 /proc/meminfo: memFree=808300/1048576 swapFree=0/0 [pid=11896] ppid=11895 vsize=2596 CPUtime=7.95 /proc/11896/stat : 11896 (aspuncud-user-1) S 11895 11896 2160 34817 2160 4202496 574 63522 0 41 0 0 765 30 18 0 1 0 55974105 2658304 298 1283457024 134512640 135304128 4289574112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11896/statm: 649 298 251 194 0 36 0 [pid=11905] ppid=11896 vsize=128948 CPUtime=94.02 /proc/11905/stat : 11905 (unclasp) R 11896 11896 2160 34817 2160 4202496 1690132 0 7 0 8720 682 0 0 25 0 1 0 55974110 132042752 29949 1283457024 134512640 135121179 4291139680 18446744073709551615 4159124549 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/11905/statm: 32237 29949 321 149 0 31428 0 Current children cumulated CPU time (s) 101.97 Current children cumulated vsize (KiB) 131544 [startup+162.305 s] /proc/loadavg: 1.00 1.02 1.00 2/35 11916 /proc/meminfo: memFree=808060/1048576 swapFree=0/0 [pid=11896] ppid=11895 vsize=2596 CPUtime=7.95 /proc/11896/stat : 11896 (aspuncud-user-1) S 11895 11896 2160 34817 2160 4202496 574 63522 0 41 0 0 765 30 18 0 1 0 55974105 2658304 298 1283457024 134512640 135304128 4289574112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11896/statm: 649 298 251 194 0 36 0 [pid=11905] ppid=11896 vsize=133196 CPUtime=153.97 /proc/11905/stat : 11905 (unclasp) R 11896 11896 2160 34817 2160 4202496 2788731 0 7 0 14273 1124 0 0 25 0 1 0 55974110 136392704 30933 1283457024 134512640 135121179 4291139680 18446744073709551615 134979215 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/11905/statm: 33299 30933 321 149 0 32490 0 Current children cumulated CPU time (s) 161.92 Current children cumulated vsize (KiB) 135792 [startup+222.308 s] /proc/loadavg: 1.00 1.01 1.00 2/35 11916 /proc/meminfo: memFree=807936/1048576 swapFree=0/0 [pid=11896] ppid=11895 vsize=2596 CPUtime=7.95 /proc/11896/stat : 11896 (aspuncud-user-1) S 11895 11896 2160 34817 2160 4202496 574 63522 0 41 0 0 765 30 18 0 1 0 55974105 2658304 298 1283457024 134512640 135304128 4289574112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11896/statm: 649 298 251 194 0 36 0 [pid=11905] ppid=11896 vsize=129324 CPUtime=213.94 /proc/11905/stat : 11905 (unclasp) R 11896 11896 2160 34817 2160 4202496 3872677 0 7 0 19826 1568 0 0 25 0 1 0 55974110 132427776 30007 1283457024 134512640 135121179 4291139680 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/11905/statm: 32331 30007 321 149 0 31522 0 Current children cumulated CPU time (s) 221.89 Current children cumulated vsize (KiB) 131920 [startup+282.309 s] /proc/loadavg: 1.00 1.01 1.00 2/35 11916 /proc/meminfo: memFree=807688/1048576 swapFree=0/0 [pid=11896] ppid=11895 vsize=2596 CPUtime=7.95 /proc/11896/stat : 11896 (aspuncud-user-1) S 11895 11896 2160 34817 2160 4202496 574 63522 0 41 0 0 765 30 18 0 1 0 55974105 2658304 298 1283457024 134512640 135304128 4289574112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11896/statm: 649 298 251 194 0 36 0 [pid=11905] ppid=11896 vsize=129328 CPUtime=273.91 /proc/11905/stat : 11905 (unclasp) R 11896 11896 2160 34817 2160 4202496 4944432 0 7 0 25378 2013 0 0 25 0 1 0 55974110 132431872 30023 1283457024 134512640 135121179 4291139680 18446744073709551615 134734361 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/11905/statm: 32332 30023 321 149 0 31523 0 Current children cumulated CPU time (s) 281.86 Current children cumulated vsize (KiB) 131924 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.511 s] /proc/loadavg: 1.00 1.01 1.00 2/35 11916 /proc/meminfo: memFree=807688/1048576 swapFree=0/0 [pid=11896] ppid=11895 vsize=2596 CPUtime=7.95 /proc/11896/stat : 11896 (aspuncud-user-1) S 11895 11896 2160 34817 2160 4202496 574 63522 0 41 0 0 765 30 18 0 1 0 55974105 2658304 298 1283457024 134512640 135304128 4289574112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/11896/statm: 649 298 251 194 0 36 0 [pid=11905] ppid=11896 vsize=129328 CPUtime=282.1 /proc/11905/stat : 11905 (unclasp) R 11896 11896 2160 34817 2160 4202496 5090512 0 7 0 26132 2078 0 0 25 0 1 0 55974110 132431872 30025 1283457024 134512640 135121179 4291139680 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/11905/statm: 32332 30025 321 149 0 31523 0 Current children cumulated CPU time (s) 290.05 Current children cumulated vsize (KiB) 131924 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.598 CPU time (s): 290.098 CPU user time (s): 268.989 CPU system time (s): 21.1093 CPU usage (%): 99.828 Max. virtual memory (cumulated for all children) (KiB): 249024 getrusage(RUSAGE_CHILDREN,...) data: user time used= 268.989 system time used= 21.1093 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 5157018 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= 9341 involuntary context switches= 11091 runsolver used 0 second user time and 0 second system time The end