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/rand796.cudf.user-upgrades.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/user-upgrades/rand796.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand796.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/35 11392
/proc/meminfo: memFree=932204/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=3020 CPUtime=0
/proc/11392/stat : 11392 (runsolver) D 11391 11392 2160 34817 2160 4202560 73 0 0 0 0 0 0 0 25 0 1 0 55694326 3092480 94 1283457024 134512640 134586868 4294236304 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/11392/statm: 755 94 62 19 0 54 0

[startup+0.185404 s]
/proc/loadavg: 1.00 1.05 1.01 2/35 11392
/proc/meminfo: memFree=932204/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=2596 CPUtime=0
/proc/11392/stat : 11392 (aspuncud-user-1) S 11391 11392 2160 34817 2160 4202496 574 1513 0 3 0 0 0 0 25 0 1 0 55694326 2658304 298 1283457024 134512640 135304128 4291167840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11392/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.205403 s]
/proc/loadavg: 1.00 1.05 1.01 2/35 11392
/proc/meminfo: memFree=932204/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=2596 CPUtime=0
/proc/11392/stat : 11392 (aspuncud-user-1) S 11391 11392 2160 34817 2160 4202496 574 1513 0 3 0 0 0 0 25 0 1 0 55694326 2658304 298 1283457024 134512640 135304128 4291167840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11392/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.305397 s]
/proc/loadavg: 1.00 1.05 1.01 2/35 11392
/proc/meminfo: memFree=932204/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=2596 CPUtime=0
/proc/11392/stat : 11392 (aspuncud-user-1) S 11391 11392 2160 34817 2160 4202496 574 1513 0 3 0 0 0 0 25 0 1 0 55694326 2658304 298 1283457024 134512640 135304128 4291167840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11392/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.710632 s]
/proc/loadavg: 1.00 1.05 1.01 2/35 11392
/proc/meminfo: memFree=932204/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=2596 CPUtime=0
/proc/11392/stat : 11392 (aspuncud-user-1) S 11391 11392 2160 34817 2160 4202496 574 1513 0 3 0 0 0 0 25 0 1 0 55694326 2658304 298 1283457024 134512640 135304128 4291167840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11392/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.51075 s]
/proc/loadavg: 1.00 1.05 1.01 2/39 11404
/proc/meminfo: memFree=913220/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=2596 CPUtime=0
/proc/11392/stat : 11392 (aspuncud-user-1) S 11391 11392 2160 34817 2160 4202496 574 1513 0 3 0 0 0 0 25 0 1 0 55694326 2658304 298 1283457024 134512640 135304128 4291167840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11392/statm: 649 298 251 194 0 36 0
[pid=11401] ppid=11392 vsize=3440 CPUtime=0
/proc/11401/stat : 11401 (unclasp) S 11392 11392 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 25 0 1 0 55694330 3522560 271 1283457024 134512640 135121179 4288064352 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/11401/statm: 860 271 240 149 0 51 0
[pid=11402] ppid=11392 vsize=2692 CPUtime=0
/proc/11402/stat : 11402 (gringo) S 11392 11392 2160 34817 2160 4202496 386 0 23 0 0 0 0 0 24 0 1 0 55694330 2756608 281 1283457024 134512640 137056543 4293034768 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/11402/statm: 673 281 252 622 0 48 0
[pid=11403] ppid=11392 vsize=28108 CPUtime=1.28
/proc/11403/stat : 11403 (cudf2lp) R 11392 11392 2160 34817 2160 4202496 7932 0 15 0 128 0 0 0 25 0 1 0 55694330 28782592 6208 1283457024 134512640 135786343 4288065856 18446744073709551615 135044613 0 0 6 0 0 0 0 17 0 0 0 0
/proc/11403/statm: 7027 6208 128 311 0 6714 0
Current children cumulated CPU time (s) 1.28
Current children cumulated vsize (KiB) 36836

[startup+3.11093 s]
/proc/loadavg: 1.00 1.05 1.01 2/39 11404
/proc/meminfo: memFree=898340/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=2596 CPUtime=0
/proc/11392/stat : 11392 (aspuncud-user-1) S 11391 11392 2160 34817 2160 4202496 574 1513 0 3 0 0 0 0 25 0 1 0 55694326 2658304 298 1283457024 134512640 135304128 4291167840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11392/statm: 649 298 251 194 0 36 0
[pid=11401] ppid=11392 vsize=11948 CPUtime=0.06
/proc/11401/stat : 11401 (unclasp) S 11392 11392 2160 34817 2160 4202496 2859 0 6 0 4 2 0 0 18 0 1 0 55694330 12234752 2343 1283457024 134512640 135121179 4288064352 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/11401/statm: 2987 2343 275 149 0 2178 0
[pid=11402] ppid=11392 vsize=16236 CPUtime=0.38
/proc/11402/stat : 11402 (gringo) R 11392 11392 2160 34817 2160 4202496 4391 0 23 0 38 0 0 0 18 0 1 0 55694330 16625664 2804 1283457024 134512640 137056543 4293034768 18446744073709551615 134913968 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11402/statm: 4059 2804 253 622 0 3434 0
[pid=11403] ppid=11392 vsize=44560 CPUtime=2.43
/proc/11403/stat : 11403 (cudf2lp) R 11392 11392 2160 34817 2160 4202496 13951 0 15 0 240 3 0 0 25 0 1 0 55694330 45629440 10934 1283457024 134512640 135786343 4288065856 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/11403/statm: 11140 10934 139 311 0 10827 0
Current children cumulated CPU time (s) 2.87
Current children cumulated vsize (KiB) 75340

[startup+6.3119 s]
/proc/loadavg: 1.00 1.05 1.01 3/39 11404
/proc/meminfo: memFree=797344/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=2596 CPUtime=3
/proc/11392/stat : 11392 (aspuncud-user-1) S 11391 11392 2160 34817 2160 4202496 574 15467 0 18 0 0 294 6 18 0 1 0 55694326 2658304 298 1283457024 134512640 135304128 4291167840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11392/statm: 649 298 251 194 0 36 0
[pid=11401] ppid=11392 vsize=53004 CPUtime=0.32
/proc/11401/stat : 11401 (unclasp) R 11392 11392 2160 34817 2160 4202496 15204 0 6 0 26 6 0 0 18 0 1 0 55694330 54276096 12392 1283457024 134512640 135121179 4288064352 18446744073709551615 134786168 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11401/statm: 13251 12392 276 149 0 12442 0
[pid=11402] ppid=11392 vsize=74988 CPUtime=2.74
/proc/11402/stat : 11402 (gringo) R 11392 11392 2160 34817 2160 4202496 25181 0 23 0 265 9 0 0 18 0 1 0 55694330 76787712 15000 1283457024 134512640 137056543 4293034768 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11402/statm: 18747 15000 268 622 0 18122 0
Current children cumulated CPU time (s) 6.06
Current children cumulated vsize (KiB) 130588

[startup+12.7153 s]
/proc/loadavg: 1.07 1.06 1.02 2/37 11405
/proc/meminfo: memFree=809040/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=2596 CPUtime=7.98
/proc/11392/stat : 11392 (aspuncud-user-1) S 11391 11392 2160 34817 2160 4202496 574 63547 0 41 0 0 770 28 18 0 1 0 55694326 2658304 298 1283457024 134512640 135304128 4291167840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11392/statm: 649 298 251 194 0 36 0
[pid=11401] ppid=11392 vsize=128568 CPUtime=4.46
/proc/11401/stat : 11401 (unclasp) R 11392 11392 2160 34817 2160 4202496 86743 0 7 0 408 38 0 0 25 0 1 0 55694330 131653632 29844 1283457024 134512640 135121179 4288064352 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11401/statm: 32142 29844 321 149 0 31333 0
Current children cumulated CPU time (s) 12.44
Current children cumulated vsize (KiB) 131164

[startup+25.5104 s]
/proc/loadavg: 1.06 1.06 1.02 2/37 11406
/proc/meminfo: memFree=808544/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=2596 CPUtime=7.98
/proc/11392/stat : 11392 (aspuncud-user-1) S 11391 11392 2160 34817 2160 4202496 574 63547 0 41 0 0 770 28 18 0 1 0 55694326 2658304 298 1283457024 134512640 135304128 4291167840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11392/statm: 649 298 251 194 0 36 0
[pid=11401] ppid=11392 vsize=128568 CPUtime=17.25
/proc/11401/stat : 11401 (unclasp) R 11392 11392 2160 34817 2160 4202496 309368 0 7 0 1581 144 0 0 25 0 1 0 55694330 131653632 29855 1283457024 134512640 135121179 4288064352 18446744073709551615 134734434 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11401/statm: 32142 29855 321 149 0 31333 0
Current children cumulated CPU time (s) 25.23
Current children cumulated vsize (KiB) 131164

[startup+51.1096 s]
/proc/loadavg: 1.04 1.05 1.01 2/37 11409
/proc/meminfo: memFree=806436/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=2596 CPUtime=7.98
/proc/11392/stat : 11392 (aspuncud-user-1) S 11391 11392 2160 34817 2160 4202496 574 63547 0 41 0 0 770 28 18 0 1 0 55694326 2658304 298 1283457024 134512640 135304128 4291167840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11392/statm: 649 298 251 194 0 36 0
[pid=11401] ppid=11392 vsize=132200 CPUtime=42.83
/proc/11401/stat : 11401 (unclasp) R 11392 11392 2160 34817 2160 4202496 759829 0 7 0 3949 334 0 0 25 0 1 0 55694330 135372800 30774 1283457024 134512640 135121179 4288064352 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11401/statm: 33050 30774 321 149 0 32241 0
Current children cumulated CPU time (s) 50.81
Current children cumulated vsize (KiB) 134796

[startup+102.305 s]
/proc/loadavg: 1.01 1.04 1.01 2/36 11412
/proc/meminfo: memFree=808436/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=2596 CPUtime=7.98
/proc/11392/stat : 11392 (aspuncud-user-1) S 11391 11392 2160 34817 2160 4202496 574 63547 0 41 0 0 770 28 18 0 1 0 55694326 2658304 298 1283457024 134512640 135304128 4291167840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11392/statm: 649 298 251 194 0 36 0
[pid=11401] ppid=11392 vsize=128992 CPUtime=94
/proc/11401/stat : 11401 (unclasp) R 11392 11392 2160 34817 2160 4202496 1656050 0 7 0 8676 724 0 0 25 0 1 0 55694330 132087808 29979 1283457024 134512640 135121179 4288064352 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11401/statm: 32248 29979 321 149 0 31439 0
Current children cumulated CPU time (s) 101.98
Current children cumulated vsize (KiB) 131588

[startup+162.308 s]
/proc/loadavg: 1.00 1.03 1.00 2/35 11412
/proc/meminfo: memFree=808196/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=2596 CPUtime=7.98
/proc/11392/stat : 11392 (aspuncud-user-1) S 11391 11392 2160 34817 2160 4202496 574 63547 0 41 0 0 770 28 18 0 1 0 55694326 2658304 298 1283457024 134512640 135304128 4291167840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11392/statm: 649 298 251 194 0 36 0
[pid=11401] ppid=11392 vsize=129356 CPUtime=153.92
/proc/11401/stat : 11401 (unclasp) R 11392 11392 2160 34817 2160 4202496 2729309 0 7 0 14202 1190 0 0 25 0 1 0 55694330 132460544 29998 1283457024 134512640 135121179 4288064352 18446744073709551615 134734464 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11401/statm: 32339 29998 321 149 0 31530 0
Current children cumulated CPU time (s) 161.9
Current children cumulated vsize (KiB) 131952

[startup+222.309 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 11412
/proc/meminfo: memFree=808072/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=2596 CPUtime=7.98
/proc/11392/stat : 11392 (aspuncud-user-1) S 11391 11392 2160 34817 2160 4202496 574 63547 0 41 0 0 770 28 18 0 1 0 55694326 2658304 298 1283457024 134512640 135304128 4291167840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11392/statm: 649 298 251 194 0 36 0
[pid=11401] ppid=11392 vsize=129368 CPUtime=213.86
/proc/11401/stat : 11401 (unclasp) R 11392 11392 2160 34817 2160 4202496 3801083 0 7 0 19748 1638 0 0 25 0 1 0 55694330 132472832 30008 1283457024 134512640 135121179 4288064352 18446744073709551615 134849098 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11401/statm: 32342 30008 321 149 0 31533 0
Current children cumulated CPU time (s) 221.84
Current children cumulated vsize (KiB) 131964

[startup+282.307 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 11412
/proc/meminfo: memFree=807824/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=2596 CPUtime=7.98
/proc/11392/stat : 11392 (aspuncud-user-1) S 11391 11392 2160 34817 2160 4202496 574 63547 0 41 0 0 770 28 18 0 1 0 55694326 2658304 298 1283457024 134512640 135304128 4291167840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11392/statm: 649 298 251 194 0 36 0
[pid=11401] ppid=11392 vsize=133804 CPUtime=273.81
/proc/11401/stat : 11401 (unclasp) R 11392 11392 2160 34817 2160 4202496 4868079 0 7 0 25308 2073 0 0 25 0 1 0 55694330 137015296 31003 1283457024 134512640 135121179 4288064352 18446744073709551615 4158302998 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11401/statm: 33451 31003 321 149 0 32642 0
Current children cumulated CPU time (s) 281.79
Current children cumulated vsize (KiB) 136400



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.61 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 11412
/proc/meminfo: memFree=807824/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=2596 CPUtime=7.98
/proc/11392/stat : 11392 (aspuncud-user-1) S 11391 11392 2160 34817 2160 4202496 574 63547 0 41 0 0 770 28 18 0 1 0 55694326 2658304 298 1283457024 134512640 135304128 4291167840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11392/statm: 649 298 251 194 0 36 0
[pid=11401] ppid=11392 vsize=129372 CPUtime=282.11
/proc/11401/stat : 11401 (unclasp) R 11392 11392 2160 34817 2160 4202496 5005663 0 7 0 26082 2129 0 0 25 0 1 0 55694330 132476928 30038 1283457024 134512640 135121179 4288064352 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11401/statm: 32343 30038 321 149 0 31534 0
Current children cumulated CPU time (s) 290.09
Current children cumulated vsize (KiB) 131968

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

Solver just ended. Dumping a history of the last processes samples

[startup+290.61 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 11412
/proc/meminfo: memFree=807824/1048576 swapFree=0/0
[pid=11392] ppid=11391 vsize=2596 CPUtime=7.98
/proc/11392/stat : 11392 (aspuncud-user-1) S 11391 11392 2160 34817 2160 4202496 574 63547 0 41 0 0 770 28 18 0 1 0 55694326 2658304 298 1283457024 134512640 135304128 4291167840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11392/statm: 649 298 251 194 0 36 0
[pid=11401] ppid=11392 vsize=129372 CPUtime=282.11
/proc/11401/stat : 11401 (unclasp) R 11392 11392 2160 34817 2160 4202496 5005663 0 7 0 26082 2129 0 0 25 0 1 0 55694330 132476928 30038 1283457024 134512640 135121179 4288064352 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/11401/statm: 32343 30038 321 149 0 31534 0
Current children cumulated CPU time (s) 290.09
Current children cumulated vsize (KiB) 131968

Child status: 0
Real time (s): 290.65
CPU time (s): 290.122
CPU user time (s): 268.537
CPU system time (s): 21.5853
CPU usage (%): 99.8182
Max. virtual memory (cumulated for all children) (KiB): 247456

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 268.537
system time used= 21.5853
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 5072198
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= 9359
involuntary context switches= 11104

runsolver used 0 second user time and 0 second system time

The end