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/paranoid-size/install/rand308.cudf.log.runsolver /home/competition/aspuncud-basic-1.7/aspuncud-basic /home/competition/data/install/rand308.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/paranoid-size/install/rand308.cudf.result -count(removed),-sum(solution,installedsize),-count(changed) 

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

[startup+0 s]
/proc/loadavg: 1.08 1.01 0.89 2/60 21329
/proc/meminfo: memFree=431820/1022884 swapFree=0/0
[pid=21329] ppid=21328 vsize=3152 CPUtime=0
/proc/21329/stat : 21329 (runsolver) R 21328 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115350662 3227648 33 18446744073709551615 134512640 134586868 4290729408 4290727456 4151718960 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/21329/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.150915 s]
/proc/loadavg: 1.08 1.01 0.89 2/60 21329
/proc/meminfo: memFree=431820/1022884 swapFree=0/0
[pid=21329] ppid=21328 vsize=9212 CPUtime=0.02
/proc/21329/stat : 21329 (aspuncud-basic) S 21328 21329 1733 0 -1 4202496 703 2804 0 0 0 0 1 1 20 0 1 0 115350662 9433088 365 18446744073709551615 4194304 5129932 140735179039360 140735179038016 139839138604126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21329/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200263 s]
/proc/loadavg: 1.08 1.01 0.89 2/60 21329
/proc/meminfo: memFree=431820/1022884 swapFree=0/0
[pid=21329] ppid=21328 vsize=9212 CPUtime=0.02
/proc/21329/stat : 21329 (aspuncud-basic) S 21328 21329 1733 0 -1 4202496 703 2804 0 0 0 0 1 1 20 0 1 0 115350662 9433088 365 18446744073709551615 4194304 5129932 140735179039360 140735179038016 139839138604126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21329/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300254 s]
/proc/loadavg: 1.08 1.01 0.89 2/60 21329
/proc/meminfo: memFree=431820/1022884 swapFree=0/0
[pid=21329] ppid=21328 vsize=9212 CPUtime=0.02
/proc/21329/stat : 21329 (aspuncud-basic) S 21328 21329 1733 0 -1 4202496 703 2804 0 0 0 0 1 1 20 0 1 0 115350662 9433088 365 18446744073709551615 4194304 5129932 140735179039360 140735179038016 139839138604126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21329/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700194 s]
/proc/loadavg: 1.08 1.01 0.89 2/60 21329
/proc/meminfo: memFree=431820/1022884 swapFree=0/0
[pid=21329] ppid=21328 vsize=9212 CPUtime=0.02
/proc/21329/stat : 21329 (aspuncud-basic) S 21328 21329 1733 0 -1 4202496 703 2804 0 0 0 0 1 1 20 0 1 0 115350662 9433088 365 18446744073709551615 4194304 5129932 140735179039360 140735179038016 139839138604126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21329/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50025 s]
/proc/loadavg: 1.08 1.01 0.89 2/62 21342
/proc/meminfo: memFree=373888/1022884 swapFree=0/0
[pid=21329] ppid=21328 vsize=9212 CPUtime=0.02
/proc/21329/stat : 21329 (aspuncud-basic) S 21328 21329 1733 0 -1 4202496 703 2804 0 0 0 0 1 1 20 0 1 0 115350662 9433088 365 18446744073709551615 4194304 5129932 140735179039360 140735179038016 139839138604126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21329/statm: 2303 365 303 229 0 63 0
[pid=21342] ppid=21329 vsize=50676 CPUtime=1.39
/proc/21342/stat : 21342 (cudf2lp) R 21329 21329 1733 0 -1 4202496 15076 0 1 0 132 7 0 0 20 0 1 0 115350667 51892224 11679 18446744073709551615 4194304 5690517 140733312332944 140733312330584 4355406 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/21342/statm: 12669 11679 160 366 0 12300 0
Current children cumulated CPU time (s) 1.41
Current children cumulated vsize (KiB) 59888

[startup+3.10034 s]
/proc/loadavg: 1.08 1.01 0.89 2/62 21342
/proc/meminfo: memFree=321312/1022884 swapFree=0/0
[pid=21329] ppid=21328 vsize=9212 CPUtime=0.02
/proc/21329/stat : 21329 (aspuncud-basic) S 21328 21329 1733 0 -1 4202496 703 2804 0 0 0 0 1 1 20 0 1 0 115350662 9433088 365 18446744073709551615 4194304 5129932 140735179039360 140735179038016 139839138604126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21329/statm: 2303 365 303 229 0 63 0
[pid=21342] ppid=21329 vsize=114764 CPUtime=2.96
/proc/21342/stat : 21342 (cudf2lp) R 21329 21329 1733 0 -1 4202496 39316 0 1 0 281 15 0 0 20 0 1 0 115350667 117518336 28361 18446744073709551615 4194304 5690517 140733312332944 140733312330120 4632064 0 0 16781316 0 0 0 0 17 0 0 0 6 0 0
/proc/21342/statm: 28691 28361 173 366 0 28322 0
Current children cumulated CPU time (s) 2.98
Current children cumulated vsize (KiB) 123976

[startup+6.30028 s]
/proc/loadavg: 1.07 1.01 0.89 2/62 21343
/proc/meminfo: memFree=257080/1022884 swapFree=0/0
[pid=21329] ppid=21328 vsize=9212 CPUtime=3.43
/proc/21329/stat : 21329 (aspuncud-basic) S 21328 21329 1733 0 -1 4202496 732 42123 0 1 0 0 321 22 20 0 1 0 115350662 9433088 365 18446744073709551615 4194304 5129932 140735179039360 140735179038016 139839138604126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21329/statm: 2303 365 303 229 0 63 0
[pid=21343] ppid=21329 vsize=231428 CPUtime=2.73
/proc/21343/stat : 21343 (gringo) R 21329 21329 1733 0 -1 4202496 57443 0 0 0 254 19 0 0 20 0 1 0 115351017 236982272 48163 18446744073709551615 4194304 6531320 140733595037728 140733595034072 5554416 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21343/statm: 57857 48163 283 571 0 57278 0
Current children cumulated CPU time (s) 6.16
Current children cumulated vsize (KiB) 240640

[startup+12.7003 s]
/proc/loadavg: 1.07 1.01 0.89 2/63 21345
/proc/meminfo: memFree=264280/1022884 swapFree=0/0
[pid=21329] ppid=21328 vsize=9212 CPUtime=8.3
/proc/21329/stat : 21329 (aspuncud-basic) S 21328 21329 1733 0 -1 4202496 775 148810 0 1 0 0 766 64 20 0 1 0 115350662 9433088 365 18446744073709551615 4194304 5129932 140735179039360 140735179037424 139839138604126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21329/statm: 2303 365 303 229 0 63 0
[pid=21344] ppid=21329 vsize=134164 CPUtime=4.15
/proc/21344/stat : 21344 (unclasp) R 21329 21329 1733 0 -1 4202496 39060 0 0 0 404 11 0 0 20 0 1 0 115351511 137383936 32976 18446744073709551615 4194304 6012874 140735441151568 140735441150888 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21344/statm: 33541 32976 230 444 0 33089 0
[pid=21345] ppid=21329 vsize=22320 CPUtime=0.01
/proc/21345/stat : 21345 (parse.py) S 21329 21329 1733 0 -1 4202496 1364 0 0 0 0 1 0 0 20 0 1 0 115351511 22855680 1174 18446744073709551615 4194304 6642060 140734527175856 140734527173976 139784451442464 0 0 16777220 20994 0 0 0 17 0 0 0 4 0 0
/proc/21345/statm: 5580 1174 508 598 0 666 0
Current children cumulated CPU time (s) 12.46
Current children cumulated vsize (KiB) 165696

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

[startup+12.8004 s]
/proc/loadavg: 1.07 1.01 0.89 2/63 21345
/proc/meminfo: memFree=264280/1022884 swapFree=0/0
[pid=21329] ppid=21328 vsize=9212 CPUtime=8.3
/proc/21329/stat : 21329 (aspuncud-basic) S 21328 21329 1733 0 -1 4202496 775 148810 0 1 0 0 766 64 20 0 1 0 115350662 9433088 365 18446744073709551615 4194304 5129932 140735179039360 140735179037424 139839138604126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21329/statm: 2303 365 303 229 0 63 0
[pid=21344] ppid=21329 vsize=134164 CPUtime=4.25
/proc/21344/stat : 21344 (unclasp) R 21329 21329 1733 0 -1 4202496 39060 0 0 0 414 11 0 0 20 0 1 0 115351511 137383936 32976 18446744073709551615 4194304 6012874 140735441151568 140735441150888 4548906 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21344/statm: 33541 32976 230 444 0 33089 0
[pid=21345] ppid=21329 vsize=22320 CPUtime=0.01
/proc/21345/stat : 21345 (parse.py) S 21329 21329 1733 0 -1 4202496 1364 0 0 0 0 1 0 0 20 0 1 0 115351511 22855680 1174 18446744073709551615 4194304 6642060 140734527175856 140734527173976 139784451442464 0 0 16777220 20994 0 0 0 17 0 0 0 4 0 0
/proc/21345/statm: 5580 1174 508 598 0 666 0
Current children cumulated CPU time (s) 12.56
Current children cumulated vsize (KiB) 165696

[startup+16.0003 s]
/proc/loadavg: 1.07 1.01 0.89 2/63 21345
/proc/meminfo: memFree=264280/1022884 swapFree=0/0
[pid=21329] ppid=21328 vsize=9212 CPUtime=8.3
/proc/21329/stat : 21329 (aspuncud-basic) S 21328 21329 1733 0 -1 4202496 775 148810 0 1 0 0 766 64 20 0 1 0 115350662 9433088 365 18446744073709551615 4194304 5129932 140735179039360 140735179037424 139839138604126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21329/statm: 2303 365 303 229 0 63 0
[pid=21344] ppid=21329 vsize=134164 CPUtime=7.42
/proc/21344/stat : 21344 (unclasp) R 21329 21329 1733 0 -1 4202496 39060 0 0 0 730 12 0 0 20 0 1 0 115351511 137383936 32976 18446744073709551615 4194304 6012874 140735441151568 140735441150888 4548594 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21344/statm: 33541 32976 230 444 0 33089 0
[pid=21345] ppid=21329 vsize=22320 CPUtime=0.01
/proc/21345/stat : 21345 (parse.py) S 21329 21329 1733 0 -1 4202496 1364 0 0 0 0 1 0 0 20 0 1 0 115351511 22855680 1174 18446744073709551615 4194304 6642060 140734527175856 140734527173976 139784451442464 0 0 16777220 20994 0 0 0 17 0 0 0 4 0 0
/proc/21345/statm: 5580 1174 508 598 0 666 0
Current children cumulated CPU time (s) 15.73
Current children cumulated vsize (KiB) 165696

[startup+17.6003 s]
/proc/loadavg: 1.06 1.01 0.89 2/63 21345
/proc/meminfo: memFree=264280/1022884 swapFree=0/0
[pid=21329] ppid=21328 vsize=9212 CPUtime=8.3
/proc/21329/stat : 21329 (aspuncud-basic) S 21328 21329 1733 0 -1 4202496 775 148810 0 1 0 0 766 64 20 0 1 0 115350662 9433088 365 18446744073709551615 4194304 5129932 140735179039360 140735179037424 139839138604126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21329/statm: 2303 365 303 229 0 63 0
[pid=21344] ppid=21329 vsize=134164 CPUtime=9.01
/proc/21344/stat : 21344 (unclasp) R 21329 21329 1733 0 -1 4202496 39060 0 0 0 889 12 0 0 20 0 1 0 115351511 137383936 32976 18446744073709551615 4194304 6012874 140735441151568 140735441150888 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21344/statm: 33541 32976 230 444 0 33089 0
[pid=21345] ppid=21329 vsize=22320 CPUtime=0.01
/proc/21345/stat : 21345 (parse.py) S 21329 21329 1733 0 -1 4202496 1364 0 0 0 0 1 0 0 20 0 1 0 115351511 22855680 1174 18446744073709551615 4194304 6642060 140734527175856 140734527173976 139784451442464 0 0 16777220 20994 0 0 0 17 0 0 0 4 0 0
/proc/21345/statm: 5580 1174 508 598 0 666 0
Current children cumulated CPU time (s) 17.32
Current children cumulated vsize (KiB) 165696

[startup+19.2003 s]
/proc/loadavg: 1.06 1.01 0.89 2/63 21345
/proc/meminfo: memFree=264280/1022884 swapFree=0/0
[pid=21329] ppid=21328 vsize=9212 CPUtime=8.3
/proc/21329/stat : 21329 (aspuncud-basic) S 21328 21329 1733 0 -1 4202496 775 148810 0 1 0 0 766 64 20 0 1 0 115350662 9433088 365 18446744073709551615 4194304 5129932 140735179039360 140735179037424 139839138604126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21329/statm: 2303 365 303 229 0 63 0
[pid=21344] ppid=21329 vsize=134164 CPUtime=10.6
/proc/21344/stat : 21344 (unclasp) R 21329 21329 1733 0 -1 4202496 39060 0 0 0 1048 12 0 0 20 0 1 0 115351511 137383936 32976 18446744073709551615 4194304 6012874 140735441151568 140735441150888 4548198 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21344/statm: 33541 32976 230 444 0 33089 0
[pid=21345] ppid=21329 vsize=22320 CPUtime=0.01
/proc/21345/stat : 21345 (parse.py) S 21329 21329 1733 0 -1 4202496 1364 0 0 0 0 1 0 0 20 0 1 0 115351511 22855680 1174 18446744073709551615 4194304 6642060 140734527175856 140734527173976 139784451442464 0 0 16777220 20994 0 0 0 17 0 0 0 4 0 0
/proc/21345/statm: 5580 1174 508 598 0 666 0
Current children cumulated CPU time (s) 18.91
Current children cumulated vsize (KiB) 165696

[startup+19.6003 s]
/proc/loadavg: 1.06 1.01 0.89 2/63 21345
/proc/meminfo: memFree=264280/1022884 swapFree=0/0
[pid=21329] ppid=21328 vsize=9212 CPUtime=8.3
/proc/21329/stat : 21329 (aspuncud-basic) S 21328 21329 1733 0 -1 4202496 775 148810 0 1 0 0 766 64 20 0 1 0 115350662 9433088 365 18446744073709551615 4194304 5129932 140735179039360 140735179037424 139839138604126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21329/statm: 2303 365 303 229 0 63 0
[pid=21344] ppid=21329 vsize=134164 CPUtime=10.99
/proc/21344/stat : 21344 (unclasp) R 21329 21329 1733 0 -1 4202496 39060 0 0 0 1087 12 0 0 20 0 1 0 115351511 137383936 32976 18446744073709551615 4194304 6012874 140735441151568 140735441150888 4548198 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21344/statm: 33541 32976 230 444 0 33089 0
[pid=21345] ppid=21329 vsize=22320 CPUtime=0.01
/proc/21345/stat : 21345 (parse.py) S 21329 21329 1733 0 -1 4202496 1364 0 0 0 0 1 0 0 20 0 1 0 115351511 22855680 1174 18446744073709551615 4194304 6642060 140734527175856 140734527173976 139784451442464 0 0 16777220 20994 0 0 0 17 0 0 0 4 0 0
/proc/21345/statm: 5580 1174 508 598 0 666 0
Current children cumulated CPU time (s) 19.3
Current children cumulated vsize (KiB) 165696

[startup+20.0003 s]
/proc/loadavg: 1.06 1.01 0.89 2/63 21345
/proc/meminfo: memFree=264280/1022884 swapFree=0/0
[pid=21329] ppid=21328 vsize=9212 CPUtime=8.3
/proc/21329/stat : 21329 (aspuncud-basic) S 21328 21329 1733 0 -1 4202496 775 148810 0 1 0 0 766 64 20 0 1 0 115350662 9433088 365 18446744073709551615 4194304 5129932 140735179039360 140735179037424 139839138604126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21329/statm: 2303 365 303 229 0 63 0
[pid=21344] ppid=21329 vsize=134164 CPUtime=11.39
/proc/21344/stat : 21344 (unclasp) R 21329 21329 1733 0 -1 4202496 39060 0 0 0 1126 13 0 0 20 0 1 0 115351511 137383936 32976 18446744073709551615 4194304 6012874 140735441151568 140735441150888 4548507 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21344/statm: 33541 32976 230 444 0 33089 0
[pid=21345] ppid=21329 vsize=22320 CPUtime=0.01
/proc/21345/stat : 21345 (parse.py) S 21329 21329 1733 0 -1 4202496 1364 0 0 0 0 1 0 0 20 0 1 0 115351511 22855680 1174 18446744073709551615 4194304 6642060 140734527175856 140734527173976 139784451442464 0 0 16777220 20994 0 0 0 17 0 0 0 4 0 0
/proc/21345/statm: 5580 1174 508 598 0 666 0
Current children cumulated CPU time (s) 19.7
Current children cumulated vsize (KiB) 165696

[startup+20.1003 s]
/proc/loadavg: 1.06 1.01 0.89 2/63 21345
/proc/meminfo: memFree=264280/1022884 swapFree=0/0
[pid=21329] ppid=21328 vsize=9212 CPUtime=8.3
/proc/21329/stat : 21329 (aspuncud-basic) S 21328 21329 1733 0 -1 4202496 775 148810 0 1 0 0 766 64 20 0 1 0 115350662 9433088 365 18446744073709551615 4194304 5129932 140735179039360 140735179037424 139839138604126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21329/statm: 2303 365 303 229 0 63 0
[pid=21344] ppid=21329 vsize=134164 CPUtime=11.49
/proc/21344/stat : 21344 (unclasp) R 21329 21329 1733 0 -1 4202496 39060 0 0 0 1136 13 0 0 20 0 1 0 115351511 137383936 32976 18446744073709551615 4194304 6012874 140735441151568 140735441150632 5251042 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21344/statm: 33541 32976 230 444 0 33089 0
[pid=21345] ppid=21329 vsize=22320 CPUtime=0.01
/proc/21345/stat : 21345 (parse.py) S 21329 21329 1733 0 -1 4202496 1364 0 0 0 0 1 0 0 20 0 1 0 115351511 22855680 1174 18446744073709551615 4194304 6642060 140734527175856 140734527173976 139784451442464 0 0 16777220 20994 0 0 0 17 0 0 0 4 0 0
/proc/21345/statm: 5580 1174 508 598 0 666 0
Current children cumulated CPU time (s) 19.8
Current children cumulated vsize (KiB) 165696

Child status: 0
Real time (s): 20.1563
CPU time (s): 19.8932
CPU user time (s): 19.0452
CPU system time (s): 0.848053
CPU usage (%): 98.6947
Max. virtual memory (cumulated for all children) (KiB): 456304

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 19.0452
system time used= 0.848053
maximum resident set size= 389612
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 190305
page faults= 1
swaps= 0
block input operations= 68616
block output operations= 49992
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 144
involuntary context switches= 2389

runsolver used 0.040002 second user time and 0.068004 second system time

The end