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: runsolver -s SIGUSR1 -M 1124 -C 150 -d 10 -w /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/embedded/install/rand290.cudf.log.runsolver /home/competition/aspuncud-basic-1.7/aspuncud-basic /home/competition/data/install/rand290.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/embedded/install/rand290.cudf.result -sum(solution,installedsize),-count(removed) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 150 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 180 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: 0.85 0.92 0.91 2/60 10025
/proc/meminfo: memFree=366468/1022884 swapFree=0/0
[pid=10025] ppid=10024 vsize=3152 CPUtime=0
/proc/10025/stat : 10025 (runsolver) D 10024 10025 32685 0 -1 4202560 74 0 0 0 0 0 0 0 20 0 1 0 37697748 3227648 96 18446744073709551615 134512640 134586868 4290259968 4290258016 4152165424 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/10025/statm: 788 96 64 19 0 73 0

[startup+0.137132 s]
/proc/loadavg: 0.85 0.92 0.91 2/60 10025
/proc/meminfo: memFree=366468/1022884 swapFree=0/0
[pid=10025] ppid=10024 vsize=9212 CPUtime=0.04
/proc/10025/stat : 10025 (aspuncud-basic) S 10024 10025 32685 0 -1 4202496 703 2805 0 0 0 0 2 2 20 0 1 0 37697748 9433088 365 18446744073709551615 4194304 5129932 140735502812160 140735502810816 139650995086430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/10025/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200332 s]
/proc/loadavg: 0.85 0.92 0.91 2/60 10025
/proc/meminfo: memFree=366468/1022884 swapFree=0/0
[pid=10025] ppid=10024 vsize=9212 CPUtime=0.04
/proc/10025/stat : 10025 (aspuncud-basic) S 10024 10025 32685 0 -1 4202496 703 2805 0 0 0 0 2 2 20 0 1 0 37697748 9433088 365 18446744073709551615 4194304 5129932 140735502812160 140735502810816 139650995086430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/10025/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300328 s]
/proc/loadavg: 0.85 0.92 0.91 2/60 10025
/proc/meminfo: memFree=366468/1022884 swapFree=0/0
[pid=10025] ppid=10024 vsize=9212 CPUtime=0.04
/proc/10025/stat : 10025 (aspuncud-basic) S 10024 10025 32685 0 -1 4202496 703 2805 0 0 0 0 2 2 20 0 1 0 37697748 9433088 365 18446744073709551615 4194304 5129932 140735502812160 140735502810816 139650995086430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/10025/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700237 s]
/proc/loadavg: 0.85 0.92 0.91 2/60 10025
/proc/meminfo: memFree=366468/1022884 swapFree=0/0
[pid=10025] ppid=10024 vsize=9212 CPUtime=0.04
/proc/10025/stat : 10025 (aspuncud-basic) S 10024 10025 32685 0 -1 4202496 703 2805 0 0 0 0 2 2 20 0 1 0 37697748 9433088 365 18446744073709551615 4194304 5129932 140735502812160 140735502810816 139650995086430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/10025/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50033 s]
/proc/loadavg: 0.85 0.92 0.91 2/62 10038
/proc/meminfo: memFree=331476/1022884 swapFree=0/0
[pid=10025] ppid=10024 vsize=9212 CPUtime=0.04
/proc/10025/stat : 10025 (aspuncud-basic) S 10024 10025 32685 0 -1 4202496 703 2805 0 0 0 0 2 2 20 0 1 0 37697748 9433088 365 18446744073709551615 4194304 5129932 140735502812160 140735502810816 139650995086430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/10025/statm: 2303 365 303 229 0 63 0
[pid=10038] ppid=10025 vsize=33064 CPUtime=1.36
/proc/10038/stat : 10038 (cudf2lp) R 10025 10025 32685 0 -1 4202496 9695 0 16 0 131 5 0 0 20 0 1 0 37697752 33857536 7978 18446744073709551615 4194304 5690517 140737335758640 140737335756280 4328344 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/10038/statm: 8266 7978 160 366 0 7897 0
Current children cumulated CPU time (s) 1.4
Current children cumulated vsize (KiB) 42276

[startup+3.10032 s]
/proc/loadavg: 0.85 0.92 0.91 2/62 10038
/proc/meminfo: memFree=299112/1022884 swapFree=0/0
[pid=10025] ppid=10024 vsize=9212 CPUtime=0.04
/proc/10025/stat : 10025 (aspuncud-basic) S 10024 10025 32685 0 -1 4202496 703 2805 0 0 0 0 2 2 20 0 1 0 37697748 9433088 365 18446744073709551615 4194304 5129932 140735502812160 140735502810816 139650995086430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/10025/statm: 2303 365 303 229 0 63 0
[pid=10038] ppid=10025 vsize=93028 CPUtime=2.95
/proc/10038/stat : 10038 (cudf2lp) R 10025 10025 32685 0 -1 4202496 26514 0 16 0 282 13 0 0 20 0 1 0 37697752 95260672 19803 18446744073709551615 4194304 5690517 140737335758640 140737335756280 4293680 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/10038/statm: 23257 19803 160 366 0 22888 0
Current children cumulated CPU time (s) 2.99
Current children cumulated vsize (KiB) 102240

[startup+6.30034 s]
/proc/loadavg: 0.86 0.92 0.91 2/62 10039
/proc/meminfo: memFree=309652/1022884 swapFree=0/0
[pid=10025] ppid=10024 vsize=9212 CPUtime=4.92
/proc/10025/stat : 10025 (aspuncud-basic) S 10024 10025 32685 0 -1 4202496 732 42110 0 16 0 1 462 29 20 0 1 0 37697748 9433088 365 18446744073709551615 4194304 5129932 140735502812160 140735502810816 139650995086430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/10025/statm: 2303 365 303 229 0 63 0
[pid=10039] ppid=10025 vsize=31748 CPUtime=1.07
/proc/10039/stat : 10039 (gringo) R 10025 10025 32685 0 -1 4202496 8970 0 22 0 102 5 0 0 20 0 1 0 37698252 32509952 6884 18446744073709551615 4194304 6531320 140734012453520 140734012450136 4417784 0 0 16781316 16386 0 0 0 17 0 0 0 18 0 0
/proc/10039/statm: 7937 6884 259 571 0 7358 0
Current children cumulated CPU time (s) 5.99
Current children cumulated vsize (KiB) 40960

[startup+12.7014 s]
/proc/loadavg: 0.87 0.92 0.91 2/62 10039
/proc/meminfo: memFree=10092/1022884 swapFree=0/0
[pid=10025] ppid=10024 vsize=9212 CPUtime=4.92
/proc/10025/stat : 10025 (aspuncud-basic) S 10024 10025 32685 0 -1 4202496 732 42110 0 16 0 1 462 29 20 0 1 0 37697748 9433088 365 18446744073709551615 4194304 5129932 140735502812160 140735502810816 139650995086430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/10025/statm: 2303 365 303 229 0 63 0
[pid=10039] ppid=10025 vsize=355292 CPUtime=7.24
/proc/10039/stat : 10039 (gringo) R 10025 10025 32685 0 -1 4202496 101930 0 23 0 678 46 0 0 20 0 1 0 37698252 363819008 37294 18446744073709551615 4194304 6531320 140734012453520 140734012451144 5808234 0 0 16781316 16386 0 0 0 17 0 0 0 21 0 0
/proc/10039/statm: 88823 37294 284 571 0 88244 0
Current children cumulated CPU time (s) 12.16
Current children cumulated vsize (KiB) 364504

[startup+25.5004 s]
/proc/loadavg: 0.90 0.93 0.91 2/63 10041
/proc/meminfo: memFree=250396/1022884 swapFree=0/0
[pid=10025] ppid=10024 vsize=9212 CPUtime=12.23
/proc/10025/stat : 10025 (aspuncud-basic) S 10024 10025 32685 0 -1 4202496 772 144044 0 39 0 1 1141 81 20 0 1 0 37697748 9433088 365 18446744073709551615 4194304 5129932 140735502812160 140735502810224 139650995086430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/10025/statm: 2303 365 303 229 0 63 0
[pid=10040] ppid=10025 vsize=129064 CPUtime=12.56
/proc/10040/stat : 10040 (unclasp) R 10025 10025 32685 0 -1 4202496 37580 0 17 0 1243 13 0 0 20 0 1 0 37699024 132161536 31614 18446744073709551615 4194304 6012874 140735213808176 140735213807496 4300210 0 0 16781316 16386 0 0 0 17 0 0 0 7 0 0
/proc/10040/statm: 32266 31614 226 444 0 31814 0
[pid=10041] ppid=10025 vsize=22044 CPUtime=0.02
/proc/10041/stat : 10041 (parse.py) S 10025 10025 32685 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 37699024 22573056 1129 18446744073709551615 4194304 6642060 140737301535648 140737301533928 140400267544352 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/10041/statm: 5511 1129 508 598 0 597 0
Current children cumulated CPU time (s) 24.81
Current children cumulated vsize (KiB) 160320

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

[startup+25.6006 s]
/proc/loadavg: 0.90 0.93 0.91 2/63 10041
/proc/meminfo: memFree=250396/1022884 swapFree=0/0
[pid=10025] ppid=10024 vsize=9212 CPUtime=12.23
/proc/10025/stat : 10025 (aspuncud-basic) S 10024 10025 32685 0 -1 4202496 772 144044 0 39 0 1 1141 81 20 0 1 0 37697748 9433088 365 18446744073709551615 4194304 5129932 140735502812160 140735502810224 139650995086430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/10025/statm: 2303 365 303 229 0 63 0
[pid=10040] ppid=10025 vsize=129064 CPUtime=12.66
/proc/10040/stat : 10040 (unclasp) R 10025 10025 32685 0 -1 4202496 37580 0 17 0 1253 13 0 0 20 0 1 0 37699024 132161536 31614 18446744073709551615 4194304 6012874 140735213808176 140735213807496 4548180 0 0 16781316 16386 0 0 0 17 0 0 0 7 0 0
/proc/10040/statm: 32266 31614 226 444 0 31814 0
[pid=10041] ppid=10025 vsize=22044 CPUtime=0.02
/proc/10041/stat : 10041 (parse.py) S 10025 10025 32685 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 37699024 22573056 1129 18446744073709551615 4194304 6642060 140737301535648 140737301533928 140400267544352 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/10041/statm: 5511 1129 508 598 0 597 0
Current children cumulated CPU time (s) 24.91
Current children cumulated vsize (KiB) 160320

[startup+27.2004 s]
/proc/loadavg: 0.90 0.93 0.91 2/63 10041
/proc/meminfo: memFree=250396/1022884 swapFree=0/0
[pid=10025] ppid=10024 vsize=9212 CPUtime=12.23
/proc/10025/stat : 10025 (aspuncud-basic) S 10024 10025 32685 0 -1 4202496 772 144044 0 39 0 1 1141 81 20 0 1 0 37697748 9433088 365 18446744073709551615 4194304 5129932 140735502812160 140735502810224 139650995086430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/10025/statm: 2303 365 303 229 0 63 0
[pid=10040] ppid=10025 vsize=129064 CPUtime=14.25
/proc/10040/stat : 10040 (unclasp) R 10025 10025 32685 0 -1 4202496 37580 0 17 0 1411 14 0 0 20 0 1 0 37699024 132161536 31614 18446744073709551615 4194304 6012874 140735213808176 140735213807496 4498711 0 0 16781316 16386 0 0 0 17 0 0 0 7 0 0
/proc/10040/statm: 32266 31614 226 444 0 31814 0
[pid=10041] ppid=10025 vsize=22044 CPUtime=0.02
/proc/10041/stat : 10041 (parse.py) S 10025 10025 32685 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 37699024 22573056 1129 18446744073709551615 4194304 6642060 140737301535648 140737301533928 140400267544352 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/10041/statm: 5511 1129 508 598 0 597 0
Current children cumulated CPU time (s) 26.5
Current children cumulated vsize (KiB) 160320

[startup+28.0004 s]
/proc/loadavg: 0.90 0.93 0.91 2/63 10041
/proc/meminfo: memFree=250396/1022884 swapFree=0/0
[pid=10025] ppid=10024 vsize=9212 CPUtime=12.23
/proc/10025/stat : 10025 (aspuncud-basic) S 10024 10025 32685 0 -1 4202496 772 144044 0 39 0 1 1141 81 20 0 1 0 37697748 9433088 365 18446744073709551615 4194304 5129932 140735502812160 140735502810224 139650995086430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/10025/statm: 2303 365 303 229 0 63 0
[pid=10040] ppid=10025 vsize=129064 CPUtime=15.04
/proc/10040/stat : 10040 (unclasp) R 10025 10025 32685 0 -1 4202496 37580 0 17 0 1490 14 0 0 20 0 1 0 37699024 132161536 31614 18446744073709551615 4194304 6012874 140735213808176 140735213807496 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 7 0 0
/proc/10040/statm: 32266 31614 226 444 0 31814 0
[pid=10041] ppid=10025 vsize=22044 CPUtime=0.02
/proc/10041/stat : 10041 (parse.py) S 10025 10025 32685 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 37699024 22573056 1129 18446744073709551615 4194304 6642060 140737301535648 140737301533928 140400267544352 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/10041/statm: 5511 1129 508 598 0 597 0
Current children cumulated CPU time (s) 27.29
Current children cumulated vsize (KiB) 160320

[startup+28.8004 s]
/proc/loadavg: 0.90 0.93 0.91 2/63 10041
/proc/meminfo: memFree=250396/1022884 swapFree=0/0
[pid=10025] ppid=10024 vsize=9212 CPUtime=12.23
/proc/10025/stat : 10025 (aspuncud-basic) S 10024 10025 32685 0 -1 4202496 772 144044 0 39 0 1 1141 81 20 0 1 0 37697748 9433088 365 18446744073709551615 4194304 5129932 140735502812160 140735502810224 139650995086430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/10025/statm: 2303 365 303 229 0 63 0
[pid=10040] ppid=10025 vsize=129064 CPUtime=15.84
/proc/10040/stat : 10040 (unclasp) R 10025 10025 32685 0 -1 4202496 37580 0 17 0 1570 14 0 0 20 0 1 0 37699024 132161536 31614 18446744073709551615 4194304 6012874 140735213808176 140735213807496 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 7 0 0
/proc/10040/statm: 32266 31614 226 444 0 31814 0
[pid=10041] ppid=10025 vsize=22044 CPUtime=0.02
/proc/10041/stat : 10041 (parse.py) S 10025 10025 32685 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 37699024 22573056 1129 18446744073709551615 4194304 6642060 140737301535648 140737301533928 140400267544352 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/10041/statm: 5511 1129 508 598 0 597 0
Current children cumulated CPU time (s) 28.09
Current children cumulated vsize (KiB) 160320

[startup+29.0004 s]
/proc/loadavg: 0.90 0.93 0.91 2/63 10041
/proc/meminfo: memFree=250396/1022884 swapFree=0/0
[pid=10025] ppid=10024 vsize=9212 CPUtime=12.23
/proc/10025/stat : 10025 (aspuncud-basic) S 10024 10025 32685 0 -1 4202496 772 144044 0 39 0 1 1141 81 20 0 1 0 37697748 9433088 365 18446744073709551615 4194304 5129932 140735502812160 140735502810224 139650995086430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/10025/statm: 2303 365 303 229 0 63 0
[pid=10040] ppid=10025 vsize=129064 CPUtime=16.04
/proc/10040/stat : 10040 (unclasp) R 10025 10025 32685 0 -1 4202496 37581 0 17 0 1590 14 0 0 20 0 1 0 37699024 132161536 31615 18446744073709551615 4194304 6012874 140735213808176 140735213807240 4538366 0 0 16781316 16386 0 0 0 17 0 0 0 7 0 0
/proc/10040/statm: 32266 31615 226 444 0 31814 0
[pid=10041] ppid=10025 vsize=22044 CPUtime=0.02
/proc/10041/stat : 10041 (parse.py) S 10025 10025 32685 0 -1 4202496 1321 0 0 0 1 1 0 0 20 0 1 0 37699024 22573056 1131 18446744073709551615 4194304 6642060 140737301535648 140737301533896 140400267544352 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/10041/statm: 5511 1131 508 598 0 597 0
Current children cumulated CPU time (s) 28.29
Current children cumulated vsize (KiB) 160320

[startup+29.1005 s]
/proc/loadavg: 0.90 0.93 0.91 2/63 10041
/proc/meminfo: memFree=250396/1022884 swapFree=0/0
[pid=10025] ppid=10024 vsize=9212 CPUtime=12.23
/proc/10025/stat : 10025 (aspuncud-basic) S 10024 10025 32685 0 -1 4202496 772 144044 0 39 0 1 1141 81 20 0 1 0 37697748 9433088 365 18446744073709551615 4194304 5129932 140735502812160 140735502810224 139650995086430 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/10025/statm: 2303 365 303 229 0 63 0
[pid=10040] ppid=10025 vsize=0 CPUtime=16.13
/proc/10040/stat : 10040 (unclasp) R 10025 10025 32685 0 -1 4202500 37591 0 17 0 1595 18 0 0 20 0 1 0 37699024 0 0 18446744073709551615 0 0 0 0 0 0 0 16781316 16386 18446744073709551615 0 0 17 0 0 0 7 0 0
/proc/10040/statm: 0 0 0 0 0 0 0
[pid=10041] ppid=10025 vsize=22044 CPUtime=0.02
/proc/10041/stat : 10041 (parse.py) R 10025 10025 32685 0 -1 4202496 1336 0 0 0 1 1 0 0 20 0 1 0 37699024 22573056 1144 18446744073709551615 4194304 6642060 140737301535648 140737301534552 4681768 0 0 16777220 0 0 0 0 17 0 0 0 0 0 0
/proc/10041/statm: 5511 1144 520 598 0 597 0
Current children cumulated CPU time (s) 28.38
Current children cumulated vsize (KiB) 31256

Child status: 0
Real time (s): 29.1122
CPU time (s): 28.4098
CPU user time (s): 27.3817
CPU system time (s): 1.02806
CPU usage (%): 97.5871
Max. virtual memory (cumulated for all children) (KiB): 434604

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 27.3817
system time used= 1.02806
maximum resident set size= 370696
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 184016
page faults= 56
swaps= 0
block input operations= 77944
block output operations= 49144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 137
involuntary context switches= 756

runsolver used 0.036002 second user time and 0.180011 second system time

The end