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/rand533.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand533.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand533.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.01 1.02 1.00 2/36 8813 /proc/meminfo: memFree=928692/1048576 swapFree=0/0 [pid=8813] ppid=8812 vsize=3020 CPUtime=0 /proc/8813/stat : 8813 (runsolver) D 8812 8813 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 54365951 3092480 93 1283457024 134512640 134586868 4290088096 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/8813/statm: 755 93 62 19 0 54 0 [startup+0.20019 s] /proc/loadavg: 1.01 1.02 1.00 2/36 8813 /proc/meminfo: memFree=928692/1048576 swapFree=0/0 [pid=8813] ppid=8812 vsize=2592 CPUtime=0 /proc/8813/stat : 8813 (aspuncud-user-1) S 8812 8813 2160 34817 2160 4202496 567 1522 0 3 0 0 0 0 25 0 1 0 54365951 2654208 297 1283457024 134512640 135304128 4290035024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8813/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.306141 s] /proc/loadavg: 1.01 1.02 1.00 2/36 8813 /proc/meminfo: memFree=928692/1048576 swapFree=0/0 [pid=8813] ppid=8812 vsize=2592 CPUtime=0 /proc/8813/stat : 8813 (aspuncud-user-1) S 8812 8813 2160 34817 2160 4202496 567 1522 0 3 0 0 0 0 25 0 1 0 54365951 2654208 297 1283457024 134512640 135304128 4290035024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8813/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.406171 s] /proc/loadavg: 1.01 1.02 1.00 2/36 8813 /proc/meminfo: memFree=928692/1048576 swapFree=0/0 [pid=8813] ppid=8812 vsize=2592 CPUtime=0 /proc/8813/stat : 8813 (aspuncud-user-1) S 8812 8813 2160 34817 2160 4202496 567 1522 0 3 0 0 0 0 25 0 1 0 54365951 2654208 297 1283457024 134512640 135304128 4290035024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8813/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.706237 s] /proc/loadavg: 1.01 1.02 1.00 2/36 8813 /proc/meminfo: memFree=928692/1048576 swapFree=0/0 [pid=8813] ppid=8812 vsize=2592 CPUtime=0 /proc/8813/stat : 8813 (aspuncud-user-1) S 8812 8813 2160 34817 2160 4202496 567 1522 0 3 0 0 0 0 25 0 1 0 54365951 2654208 297 1283457024 134512640 135304128 4290035024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8813/statm: 648 297 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.50656 s] /proc/loadavg: 1.01 1.02 1.00 2/40 8824 /proc/meminfo: memFree=908708/1048576 swapFree=0/0 [pid=8813] ppid=8812 vsize=2592 CPUtime=0 /proc/8813/stat : 8813 (aspuncud-user-1) S 8812 8813 2160 34817 2160 4202496 567 1522 0 3 0 0 0 0 25 0 1 0 54365951 2654208 297 1283457024 134512640 135304128 4290035024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8813/statm: 648 297 251 194 0 35 0 [pid=8822] ppid=8813 vsize=3448 CPUtime=0 /proc/8822/stat : 8822 (unclasp) S 8813 8813 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 24 0 1 0 54365956 3530752 272 1283457024 134512640 135121179 4289906688 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/8822/statm: 862 272 240 149 0 53 0 [pid=8823] ppid=8813 vsize=2688 CPUtime=0 /proc/8823/stat : 8823 (gringo) S 8813 8813 2160 34817 2160 4202496 384 0 23 0 0 0 0 0 24 0 1 0 54365956 2752512 280 1283457024 134512640 137056543 4294787536 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/8823/statm: 672 280 252 622 0 47 0 [pid=8824] ppid=8813 vsize=28108 CPUtime=1.28 /proc/8824/stat : 8824 (cudf2lp) R 8813 8813 2160 34817 2160 4202496 7902 0 15 0 124 4 0 0 25 0 1 0 54365956 28782592 6179 1283457024 134512640 135786343 4293120176 18446744073709551615 135052128 0 0 6 0 0 0 0 17 0 0 0 0 /proc/8824/statm: 7027 6179 128 311 0 6714 0 Current children cumulated CPU time (s) 1.28 Current children cumulated vsize (KiB) 36836 [startup+3.10688 s] /proc/loadavg: 1.01 1.02 1.00 2/40 8824 /proc/meminfo: memFree=885892/1048576 swapFree=0/0 [pid=8813] ppid=8812 vsize=2592 CPUtime=0 /proc/8813/stat : 8813 (aspuncud-user-1) S 8812 8813 2160 34817 2160 4202496 567 1522 0 3 0 0 0 0 25 0 1 0 54365951 2654208 297 1283457024 134512640 135304128 4290035024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8813/statm: 648 297 251 194 0 35 0 [pid=8822] ppid=8813 vsize=10932 CPUtime=0.06 /proc/8822/stat : 8822 (unclasp) S 8813 8813 2160 34817 2160 4202496 2491 0 6 0 5 1 0 0 18 0 1 0 54365956 11194368 2158 1283457024 134512640 135121179 4289906688 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/8822/statm: 2733 2158 275 149 0 1924 0 [pid=8823] ppid=8813 vsize=12820 CPUtime=0.37 /proc/8823/stat : 8823 (gringo) R 8813 8813 2160 34817 2160 4202496 3545 0 23 0 36 1 0 0 18 0 1 0 54365956 13127680 2505 1283457024 134512640 137056543 4294787536 18446744073709551615 136285087 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8823/statm: 3205 2505 253 622 0 2580 0 [pid=8824] ppid=8813 vsize=44560 CPUtime=2.43 /proc/8824/stat : 8824 (cudf2lp) R 8813 8813 2160 34817 2160 4202496 13950 0 15 0 236 7 0 0 25 0 1 0 54365956 45629440 10934 1283457024 134512640 135786343 4293120176 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/8824/statm: 11140 10934 139 311 0 10827 0 Current children cumulated CPU time (s) 2.86 Current children cumulated vsize (KiB) 70904 [startup+6.30753 s] /proc/loadavg: 1.09 1.04 1.01 3/40 8824 /proc/meminfo: memFree=792584/1048576 swapFree=0/0 [pid=8813] ppid=8812 vsize=2592 CPUtime=0 /proc/8813/stat : 8813 (aspuncud-user-1) S 8812 8813 2160 34817 2160 4202496 567 1522 0 3 0 0 0 0 25 0 1 0 54365951 2654208 297 1283457024 134512640 135304128 4290035024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8813/statm: 648 297 251 194 0 35 0 [pid=8822] ppid=8813 vsize=51668 CPUtime=0.31 /proc/8822/stat : 8822 (unclasp) S 8813 8813 2160 34817 2160 4202496 14871 0 6 0 26 5 0 0 18 0 1 0 54365956 52908032 12060 1283457024 134512640 135121179 4289906688 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/8822/statm: 12917 12060 275 149 0 12108 0 [pid=8823] ppid=8813 vsize=72092 CPUtime=2.64 /proc/8823/stat : 8823 (gringo) S 8813 8813 2160 34817 2160 4202496 24278 0 23 0 249 15 0 0 18 0 1 0 54365956 73822208 14260 1283457024 134512640 137056543 4294787536 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/8823/statm: 18023 14260 253 622 0 17398 0 [pid=8824] ppid=8813 vsize=24732 CPUtime=3.09 /proc/8824/stat : 8824 (cudf2lp) R 8813 8813 2160 34817 2160 4202496 13950 0 15 0 300 9 0 0 25 0 1 0 54365956 25325568 3959 1283457024 134512640 135786343 4293120176 18446744073709551615 135407694 0 0 6 0 0 0 0 17 0 0 0 0 /proc/8824/statm: 6183 3959 139 311 0 5870 0 Current children cumulated CPU time (s) 6.04 Current children cumulated vsize (KiB) 151084 [startup+12.7119 s] /proc/loadavg: 1.08 1.04 1.00 2/38 8824 /proc/meminfo: memFree=805024/1048576 swapFree=0/0 [pid=8813] ppid=8812 vsize=2592 CPUtime=7.97 /proc/8813/stat : 8813 (aspuncud-user-1) S 8812 8813 2160 34817 2160 4202496 567 63517 0 41 0 0 762 35 18 0 1 0 54365951 2654208 297 1283457024 134512640 135304128 4290035024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8813/statm: 648 297 251 194 0 35 0 [pid=8822] ppid=8813 vsize=128776 CPUtime=4.45 /proc/8822/stat : 8822 (unclasp) R 8813 8813 2160 34817 2160 4202496 88763 0 7 0 409 36 0 0 25 0 1 0 54365956 131866624 29979 1283457024 134512640 135121179 4289906688 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8822/statm: 32194 29979 321 149 0 31385 0 Current children cumulated CPU time (s) 12.42 Current children cumulated vsize (KiB) 131368 [startup+25.5063 s] /proc/loadavg: 1.07 1.03 1.00 2/38 8824 /proc/meminfo: memFree=804900/1048576 swapFree=0/0 [pid=8813] ppid=8812 vsize=2592 CPUtime=7.97 /proc/8813/stat : 8813 (aspuncud-user-1) S 8812 8813 2160 34817 2160 4202496 567 63517 0 41 0 0 762 35 18 0 1 0 54365951 2654208 297 1283457024 134512640 135304128 4290035024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8813/statm: 648 297 251 194 0 35 0 [pid=8822] ppid=8813 vsize=131844 CPUtime=17.24 /proc/8822/stat : 8822 (unclasp) R 8813 8813 2160 34817 2160 4202496 325664 0 7 0 1588 136 0 0 25 0 1 0 54365956 135008256 30422 1283457024 134512640 135121179 4289906688 18446744073709551615 134990465 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8822/statm: 32961 30422 321 149 0 32152 0 Current children cumulated CPU time (s) 25.21 Current children cumulated vsize (KiB) 134436 [startup+51.105 s] /proc/loadavg: 1.04 1.03 1.00 2/40 8827 /proc/meminfo: memFree=805000/1048576 swapFree=0/0 [pid=8813] ppid=8812 vsize=2592 CPUtime=7.97 /proc/8813/stat : 8813 (aspuncud-user-1) S 8812 8813 2160 34817 2160 4202496 567 63517 0 41 0 0 762 35 18 0 1 0 54365951 2654208 297 1283457024 134512640 135304128 4290035024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8813/statm: 648 297 251 194 0 35 0 [pid=8822] ppid=8813 vsize=128780 CPUtime=42.83 /proc/8822/stat : 8822 (unclasp) R 8813 8813 2160 34817 2160 4202496 793789 0 7 0 3929 354 0 0 25 0 1 0 54365956 131870720 29995 1283457024 134512640 135121179 4289906688 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8822/statm: 32195 29995 321 149 0 31386 0 Current children cumulated CPU time (s) 50.8 Current children cumulated vsize (KiB) 131372 [startup+102.312 s] /proc/loadavg: 1.02 1.02 1.00 2/40 8832 /proc/meminfo: memFree=804380/1048576 swapFree=0/0 [pid=8813] ppid=8812 vsize=2592 CPUtime=7.97 /proc/8813/stat : 8813 (aspuncud-user-1) S 8812 8813 2160 34817 2160 4202496 567 63517 0 41 0 0 762 35 18 0 1 0 54365951 2654208 297 1283457024 134512640 135304128 4290035024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8813/statm: 648 297 251 194 0 35 0 [pid=8822] ppid=8813 vsize=129352 CPUtime=93.99 /proc/8822/stat : 8822 (unclasp) R 8813 8813 2160 34817 2160 4202496 1695950 0 7 0 8669 730 0 0 25 0 1 0 54365956 132456448 30076 1283457024 134512640 135121179 4289906688 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8822/statm: 32338 30076 321 149 0 31529 0 Current children cumulated CPU time (s) 101.96 Current children cumulated vsize (KiB) 131944 [startup+162.302 s] /proc/loadavg: 1.05 1.03 1.00 2/39 8835 /proc/meminfo: memFree=804272/1048576 swapFree=0/0 [pid=8813] ppid=8812 vsize=2592 CPUtime=7.97 /proc/8813/stat : 8813 (aspuncud-user-1) S 8812 8813 2160 34817 2160 4202496 567 63517 0 41 0 0 762 35 18 0 1 0 54365951 2654208 297 1283457024 134512640 135304128 4290035024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8813/statm: 648 297 251 194 0 35 0 [pid=8822] ppid=8813 vsize=129152 CPUtime=153.92 /proc/8822/stat : 8822 (unclasp) R 8813 8813 2160 34817 2160 4202496 2734234 0 7 0 14176 1216 0 0 25 0 1 0 54365956 132251648 30025 1283457024 134512640 135121179 4289906688 18446744073709551615 134734361 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8822/statm: 32288 30025 321 149 0 31479 0 Current children cumulated CPU time (s) 161.89 Current children cumulated vsize (KiB) 131744 [startup+222.31 s] /proc/loadavg: 1.02 1.02 1.00 2/38 8835 /proc/meminfo: memFree=801924/1048576 swapFree=0/0 [pid=8813] ppid=8812 vsize=2592 CPUtime=7.97 /proc/8813/stat : 8813 (aspuncud-user-1) S 8812 8813 2160 34817 2160 4202496 567 63517 0 41 0 0 762 35 18 0 1 0 54365951 2654208 297 1283457024 134512640 135304128 4290035024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8813/statm: 648 297 251 194 0 35 0 [pid=8822] ppid=8813 vsize=132236 CPUtime=213.85 /proc/8822/stat : 8822 (unclasp) R 8813 8813 2160 34817 2160 4202496 3750487 0 7 0 19749 1636 0 0 25 0 1 0 54365956 135409664 30745 1283457024 134512640 135121179 4289906688 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8822/statm: 33059 30745 321 149 0 32250 0 Current children cumulated CPU time (s) 221.82 Current children cumulated vsize (KiB) 134828 [startup+282.311 s] /proc/loadavg: 1.00 1.02 1.00 2/38 8835 /proc/meminfo: memFree=803908/1048576 swapFree=0/0 [pid=8813] ppid=8812 vsize=2592 CPUtime=7.97 /proc/8813/stat : 8813 (aspuncud-user-1) S 8812 8813 2160 34817 2160 4202496 567 63517 0 41 0 0 762 35 18 0 1 0 54365951 2654208 297 1283457024 134512640 135304128 4290035024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8813/statm: 648 297 251 194 0 35 0 [pid=8822] ppid=8813 vsize=134268 CPUtime=273.8 /proc/8822/stat : 8822 (unclasp) R 8813 8813 2160 34817 2160 4202496 4762497 0 7 0 25308 2072 0 0 25 0 1 0 54365956 137490432 31237 1283457024 134512640 135121179 4289906688 18446744073709551615 134982513 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8822/statm: 33567 31237 321 149 0 32758 0 Current children cumulated CPU time (s) 281.77 Current children cumulated vsize (KiB) 136860 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.605 s] /proc/loadavg: 1.00 1.02 1.00 2/38 8835 /proc/meminfo: memFree=804280/1048576 swapFree=0/0 [pid=8813] ppid=8812 vsize=2592 CPUtime=7.97 /proc/8813/stat : 8813 (aspuncud-user-1) S 8812 8813 2160 34817 2160 4202496 567 63517 0 41 0 0 762 35 18 0 1 0 54365951 2654208 297 1283457024 134512640 135304128 4290035024 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8813/statm: 648 297 251 194 0 35 0 [pid=8822] ppid=8813 vsize=129172 CPUtime=282.1 /proc/8822/stat : 8822 (unclasp) R 8813 8813 2160 34817 2160 4202496 4901542 0 7 0 26069 2141 0 0 25 0 1 0 54365956 132272128 29997 1283457024 134512640 135121179 4289906688 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8822/statm: 32293 29997 321 149 0 31484 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 131764 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.642 CPU time (s): 290.106 CPU user time (s): 268.325 CPU system time (s): 21.7814 CPU usage (%): 99.8156 Max. virtual memory (cumulated for all children) (KiB): 247144 getrusage(RUSAGE_CHILDREN,...) data: user time used= 268.325 system time used= 21.7814 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 4968022 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= 9350 involuntary context switches= 11109 runsolver used 0 second user time and 0 second system time The end