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/rand438.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand438.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand438.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.05 1.01 2/36 7299 /proc/meminfo: memFree=929036/1048576 swapFree=0/0 [pid=7299] ppid=7298 vsize=3024 CPUtime=0 /proc/7299/stat : 7299 (runsolver) D 7298 7299 2160 34817 2160 4202560 73 0 0 0 0 0 0 0 25 0 1 0 53543740 3096576 94 1283457024 134512640 134586868 4289516560 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/7299/statm: 756 94 62 19 0 55 0 [startup+0.117941 s] /proc/loadavg: 1.00 1.05 1.01 2/36 7299 /proc/meminfo: memFree=929036/1048576 swapFree=0/0 [pid=7299] ppid=7298 vsize=2596 CPUtime=0 /proc/7299/stat : 7299 (aspuncud-user-1) S 7298 7299 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 53543740 2658304 298 1283457024 134512640 135304128 4290770432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7299/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.205979 s] /proc/loadavg: 1.00 1.05 1.01 2/36 7299 /proc/meminfo: memFree=929036/1048576 swapFree=0/0 [pid=7299] ppid=7298 vsize=2596 CPUtime=0 /proc/7299/stat : 7299 (aspuncud-user-1) S 7298 7299 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 53543740 2658304 298 1283457024 134512640 135304128 4290770432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7299/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.309788 s] /proc/loadavg: 1.00 1.05 1.01 2/36 7299 /proc/meminfo: memFree=929036/1048576 swapFree=0/0 [pid=7299] ppid=7298 vsize=2596 CPUtime=0 /proc/7299/stat : 7299 (aspuncud-user-1) S 7298 7299 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 53543740 2658304 298 1283457024 134512640 135304128 4290770432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7299/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.709863 s] /proc/loadavg: 1.00 1.05 1.01 2/36 7299 /proc/meminfo: memFree=929036/1048576 swapFree=0/0 [pid=7299] ppid=7298 vsize=2596 CPUtime=0 /proc/7299/stat : 7299 (aspuncud-user-1) S 7298 7299 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 53543740 2658304 298 1283457024 134512640 135304128 4290770432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7299/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.51003 s] /proc/loadavg: 1.00 1.05 1.01 2/40 7310 /proc/meminfo: memFree=909920/1048576 swapFree=0/0 [pid=7299] ppid=7298 vsize=2596 CPUtime=0 /proc/7299/stat : 7299 (aspuncud-user-1) S 7298 7299 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 53543740 2658304 298 1283457024 134512640 135304128 4290770432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7299/statm: 649 298 251 194 0 36 0 [pid=7308] ppid=7299 vsize=3440 CPUtime=0 /proc/7308/stat : 7308 (unclasp) S 7299 7299 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 25 0 1 0 53543745 3522560 271 1283457024 134512640 135121179 4289710624 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/7308/statm: 860 271 240 149 0 51 0 [pid=7309] ppid=7299 vsize=2692 CPUtime=0 /proc/7309/stat : 7309 (gringo) S 7299 7299 2160 34817 2160 4202496 386 0 23 0 0 0 0 0 24 0 1 0 53543746 2756608 281 1283457024 134512640 137056543 4289709088 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/7309/statm: 673 281 252 622 0 48 0 [pid=7310] ppid=7299 vsize=28116 CPUtime=1.29 /proc/7310/stat : 7310 (cudf2lp) R 7299 7299 2160 34817 2160 4202496 7935 0 15 0 126 3 0 0 25 0 1 0 53543746 28790784 6211 1283457024 134512640 135786343 4288807696 18446744073709551615 135214656 0 0 6 0 0 0 0 17 0 0 0 0 /proc/7310/statm: 7029 6211 128 311 0 6716 0 Current children cumulated CPU time (s) 1.29 Current children cumulated vsize (KiB) 36844 [startup+3.11034 s] /proc/loadavg: 1.00 1.05 1.01 2/40 7310 /proc/meminfo: memFree=893180/1048576 swapFree=0/0 [pid=7299] ppid=7298 vsize=2596 CPUtime=0 /proc/7299/stat : 7299 (aspuncud-user-1) S 7298 7299 2160 34817 2160 4202496 574 1516 0 3 0 0 0 0 25 0 1 0 53543740 2658304 298 1283457024 134512640 135304128 4290770432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7299/statm: 649 298 251 194 0 36 0 [pid=7308] ppid=7299 vsize=11948 CPUtime=0.02 /proc/7308/stat : 7308 (unclasp) S 7299 7299 2160 34817 2160 4202496 2852 0 6 0 2 0 0 0 18 0 1 0 53543745 12234752 2336 1283457024 134512640 135121179 4289710624 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/7308/statm: 2987 2336 275 149 0 2178 0 [pid=7309] ppid=7299 vsize=16236 CPUtime=0.43 /proc/7309/stat : 7309 (gringo) S 7299 7299 2160 34817 2160 4202496 4352 0 23 0 43 0 0 0 18 0 1 0 53543746 16625664 2798 1283457024 134512640 137056543 4289709088 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/7309/statm: 4059 2798 253 622 0 3434 0 [pid=7310] ppid=7299 vsize=44568 CPUtime=2.43 /proc/7310/stat : 7310 (cudf2lp) R 7299 7299 2160 34817 2160 4202496 13952 0 15 0 236 7 0 0 25 0 1 0 53543746 45637632 10935 1283457024 134512640 135786343 4288807696 18446744073709551615 134888895 0 0 6 0 0 0 0 17 0 0 0 0 /proc/7310/statm: 11142 10935 139 311 0 10829 0 Current children cumulated CPU time (s) 2.88 Current children cumulated vsize (KiB) 75348 [startup+6.311 s] /proc/loadavg: 1.00 1.05 1.01 3/40 7310 /proc/meminfo: memFree=793672/1048576 swapFree=0/0 [pid=7299] ppid=7298 vsize=2596 CPUtime=3.18 /proc/7299/stat : 7299 (aspuncud-user-1) S 7298 7299 2160 34817 2160 4202496 574 15471 0 18 0 0 304 14 18 0 1 0 53543740 2658304 298 1283457024 134512640 135304128 4290770432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7299/statm: 649 298 251 194 0 36 0 [pid=7308] ppid=7299 vsize=53136 CPUtime=0.2 /proc/7308/stat : 7308 (unclasp) R 7299 7299 2160 34817 2160 4202496 15254 0 6 0 12 8 0 0 18 0 1 0 53543745 54411264 12442 1283457024 134512640 135121179 4289710624 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7308/statm: 13284 12442 276 149 0 12475 0 [pid=7309] ppid=7299 vsize=74996 CPUtime=2.71 /proc/7309/stat : 7309 (gringo) R 7299 7299 2160 34817 2160 4202496 25164 0 23 0 265 6 0 0 18 0 1 0 53543746 76795904 15016 1283457024 134512640 137056543 4289709088 18446744073709551615 136292971 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7309/statm: 18749 15016 268 622 0 18124 0 Current children cumulated CPU time (s) 6.09 Current children cumulated vsize (KiB) 130728 [startup+12.7129 s] /proc/loadavg: 1.00 1.04 1.01 2/38 7310 /proc/meminfo: memFree=805864/1048576 swapFree=0/0 [pid=7299] ppid=7298 vsize=2596 CPUtime=8.11 /proc/7299/stat : 7299 (aspuncud-user-1) S 7298 7299 2160 34817 2160 4202496 574 63520 0 41 0 0 776 35 18 0 1 0 53543740 2658304 298 1283457024 134512640 135304128 4290770432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7299/statm: 649 298 251 194 0 36 0 [pid=7308] ppid=7299 vsize=132360 CPUtime=4.37 /proc/7308/stat : 7308 (unclasp) R 7299 7299 2160 34817 2160 4202496 88027 0 7 0 386 51 0 0 25 0 1 0 53543745 135536640 30788 1283457024 134512640 135121179 4289710624 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7308/statm: 33090 30788 321 149 0 32281 0 Current children cumulated CPU time (s) 12.48 Current children cumulated vsize (KiB) 134956 [startup+25.5072 s] /proc/loadavg: 1.00 1.04 1.01 2/38 7310 /proc/meminfo: memFree=803260/1048576 swapFree=0/0 [pid=7299] ppid=7298 vsize=2596 CPUtime=8.11 /proc/7299/stat : 7299 (aspuncud-user-1) S 7298 7299 2160 34817 2160 4202496 574 63520 0 41 0 0 776 35 18 0 1 0 53543740 2658304 298 1283457024 134512640 135304128 4290770432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7299/statm: 649 298 251 194 0 36 0 [pid=7308] ppid=7299 vsize=132108 CPUtime=17.15 /proc/7308/stat : 7308 (unclasp) R 7299 7299 2160 34817 2160 4202496 319133 0 7 0 1568 147 0 0 25 0 1 0 53543745 135278592 30759 1283457024 134512640 135121179 4289710624 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7308/statm: 33027 30759 321 149 0 32218 0 Current children cumulated CPU time (s) 25.26 Current children cumulated vsize (KiB) 134704 [startup+51.1057 s] /proc/loadavg: 1.00 1.04 1.01 2/38 7310 /proc/meminfo: memFree=805368/1048576 swapFree=0/0 [pid=7299] ppid=7298 vsize=2596 CPUtime=8.11 /proc/7299/stat : 7299 (aspuncud-user-1) S 7298 7299 2160 34817 2160 4202496 574 63520 0 41 0 0 776 35 18 0 1 0 53543740 2658304 298 1283457024 134512640 135304128 4290770432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7299/statm: 649 298 251 194 0 36 0 [pid=7308] ppid=7299 vsize=128484 CPUtime=42.72 /proc/7308/stat : 7308 (unclasp) R 7299 7299 2160 34817 2160 4202496 776370 0 7 0 3936 336 0 0 25 0 1 0 53543745 131567616 29864 1283457024 134512640 135121179 4289710624 18446744073709551615 134734361 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7308/statm: 32121 29864 321 149 0 31312 0 Current children cumulated CPU time (s) 50.83 Current children cumulated vsize (KiB) 131080 [startup+102.313 s] /proc/loadavg: 1.00 1.03 1.00 2/38 7310 /proc/meminfo: memFree=805120/1048576 swapFree=0/0 [pid=7299] ppid=7298 vsize=2596 CPUtime=8.11 /proc/7299/stat : 7299 (aspuncud-user-1) S 7298 7299 2160 34817 2160 4202496 574 63520 0 41 0 0 776 35 18 0 1 0 53543740 2658304 298 1283457024 134512640 135304128 4290770432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7299/statm: 649 298 251 194 0 36 0 [pid=7308] ppid=7299 vsize=128984 CPUtime=93.89 /proc/7308/stat : 7308 (unclasp) R 7299 7299 2160 34817 2160 4202496 1680324 0 7 0 8649 740 0 0 25 0 1 0 53543745 132079616 29975 1283457024 134512640 135121179 4289710624 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7308/statm: 32246 29975 321 149 0 31437 0 Current children cumulated CPU time (s) 102 Current children cumulated vsize (KiB) 131580 [startup+162.305 s] /proc/loadavg: 1.00 1.02 1.00 2/38 7310 /proc/meminfo: memFree=804872/1048576 swapFree=0/0 [pid=7299] ppid=7298 vsize=2596 CPUtime=8.11 /proc/7299/stat : 7299 (aspuncud-user-1) S 7298 7299 2160 34817 2160 4202496 574 63520 0 41 0 0 776 35 18 0 1 0 53543740 2658304 298 1283457024 134512640 135304128 4290770432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7299/statm: 649 298 251 194 0 36 0 [pid=7308] ppid=7299 vsize=129348 CPUtime=153.84 /proc/7308/stat : 7308 (unclasp) R 7299 7299 2160 34817 2160 4202496 2777756 0 7 0 14158 1226 0 0 25 0 1 0 53543745 132452352 29975 1283457024 134512640 135121179 4289710624 18446744073709551615 134891399 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7308/statm: 32337 29975 321 149 0 31528 0 Current children cumulated CPU time (s) 161.95 Current children cumulated vsize (KiB) 131944 [startup+222.306 s] /proc/loadavg: 1.00 1.02 1.00 2/38 7310 /proc/meminfo: memFree=801028/1048576 swapFree=0/0 [pid=7299] ppid=7298 vsize=2596 CPUtime=8.11 /proc/7299/stat : 7299 (aspuncud-user-1) S 7298 7299 2160 34817 2160 4202496 574 63520 0 41 0 0 776 35 18 0 1 0 53543740 2658304 298 1283457024 134512640 135304128 4290770432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7299/statm: 649 298 251 194 0 36 0 [pid=7308] ppid=7299 vsize=132436 CPUtime=213.78 /proc/7308/stat : 7308 (unclasp) R 7299 7299 2160 34817 2160 4202496 3856040 0 7 0 19708 1670 0 0 25 0 1 0 53543745 135614464 30784 1283457024 134512640 135121179 4289710624 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7308/statm: 33109 30784 321 149 0 32300 0 Current children cumulated CPU time (s) 221.89 Current children cumulated vsize (KiB) 135032 [startup+282.306 s] /proc/loadavg: 1.00 1.01 1.00 2/40 7316 /proc/meminfo: memFree=804352/1048576 swapFree=0/0 [pid=7299] ppid=7298 vsize=2596 CPUtime=8.11 /proc/7299/stat : 7299 (aspuncud-user-1) S 7298 7299 2160 34817 2160 4202496 574 63520 0 41 0 0 776 35 18 0 1 0 53543740 2658304 298 1283457024 134512640 135304128 4290770432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7299/statm: 649 298 251 194 0 36 0 [pid=7308] ppid=7299 vsize=133252 CPUtime=273.74 /proc/7308/stat : 7308 (unclasp) R 7299 7299 2160 34817 2160 4202496 4916830 0 7 0 25259 2115 0 0 25 0 1 0 53543745 136450048 30981 1283457024 134512640 135121179 4289710624 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7308/statm: 33313 30981 321 149 0 32504 0 Current children cumulated CPU time (s) 281.85 Current children cumulated vsize (KiB) 135848 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.509 s] /proc/loadavg: 1.00 1.01 1.00 2/40 7317 /proc/meminfo: memFree=801748/1048576 swapFree=0/0 [pid=7299] ppid=7298 vsize=2596 CPUtime=8.11 /proc/7299/stat : 7299 (aspuncud-user-1) S 7298 7299 2160 34817 2160 4202496 574 63520 0 41 0 0 776 35 18 0 1 0 53543740 2658304 298 1283457024 134512640 135304128 4290770432 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7299/statm: 649 298 251 194 0 36 0 [pid=7308] ppid=7299 vsize=132440 CPUtime=281.94 /proc/7308/stat : 7308 (unclasp) R 7299 7299 2160 34817 2160 4202496 5062577 0 7 0 26023 2171 0 0 25 0 1 0 53543745 135618560 30803 1283457024 134512640 135121179 4289710624 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7308/statm: 33110 30803 321 149 0 32301 0 Current children cumulated CPU time (s) 290.05 Current children cumulated vsize (KiB) 135036 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.546 CPU time (s): 290.07 CPU user time (s): 267.993 CPU system time (s): 22.0774 CPU usage (%): 99.8361 Max. virtual memory (cumulated for all children) (KiB): 249160 getrusage(RUSAGE_CHILDREN,...) data: user time used= 267.993 system time used= 22.0774 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 5129066 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= 9354 involuntary context switches= 11048 runsolver used 0 second user time and 0.004 second system time The end