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/real/e69a0e36-9ef1-11df-9d4a-00163e46d37a.cudf.log.runsolver /home/competition/aspuncud-basic-1.7/aspuncud-basic /home/competition/data/real/e69a0e36-9ef1-11df-9d4a-00163e46d37a.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/embedded/real/e69a0e36-9ef1-11df-9d4a-00163e46d37a.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.99 0.97 0.91 2/59 6132
/proc/meminfo: memFree=367056/1022884 swapFree=0/0
[pid=6132] ppid=6131 vsize=3152 CPUtime=0
/proc/6132/stat : 6132 (runsolver) R 6131 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115954682 3227648 32 18446744073709551615 134512640 134586868 4292615696 4292613744 4151804976 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/6132/statm: 788 32 0 19 0 73 0

[startup+0.155184 s]
/proc/loadavg: 0.99 0.97 0.91 2/59 6132
/proc/meminfo: memFree=367056/1022884 swapFree=0/0
[pid=6132] ppid=6131 vsize=9212 CPUtime=0.02
/proc/6132/stat : 6132 (aspuncud-basic) S 6131 6132 1750 0 -1 4202496 692 2809 0 0 0 0 2 0 20 0 1 0 115954682 9433088 364 18446744073709551615 4194304 5129932 140734332211504 140734332210160 140377045550174 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6132/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200283 s]
/proc/loadavg: 0.99 0.97 0.91 2/59 6132
/proc/meminfo: memFree=367056/1022884 swapFree=0/0
[pid=6132] ppid=6131 vsize=9212 CPUtime=0.02
/proc/6132/stat : 6132 (aspuncud-basic) S 6131 6132 1750 0 -1 4202496 692 2809 0 0 0 0 2 0 20 0 1 0 115954682 9433088 364 18446744073709551615 4194304 5129932 140734332211504 140734332210160 140377045550174 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6132/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.30038 s]
/proc/loadavg: 0.99 0.97 0.91 2/59 6132
/proc/meminfo: memFree=367056/1022884 swapFree=0/0
[pid=6132] ppid=6131 vsize=9212 CPUtime=0.02
/proc/6132/stat : 6132 (aspuncud-basic) S 6131 6132 1750 0 -1 4202496 692 2809 0 0 0 0 2 0 20 0 1 0 115954682 9433088 364 18446744073709551615 4194304 5129932 140734332211504 140734332210160 140377045550174 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6132/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700209 s]
/proc/loadavg: 0.99 0.97 0.91 2/59 6132
/proc/meminfo: memFree=367056/1022884 swapFree=0/0
[pid=6132] ppid=6131 vsize=9212 CPUtime=0.02
/proc/6132/stat : 6132 (aspuncud-basic) S 6131 6132 1750 0 -1 4202496 692 2809 0 0 0 0 2 0 20 0 1 0 115954682 9433088 364 18446744073709551615 4194304 5129932 140734332211504 140734332210160 140377045550174 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6132/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 1.07 0.99 0.92 2/61 6145
/proc/meminfo: memFree=309372/1022884 swapFree=0/0
[pid=6132] ppid=6131 vsize=9212 CPUtime=0.02
/proc/6132/stat : 6132 (aspuncud-basic) S 6131 6132 1750 0 -1 4202496 692 2809 0 0 0 0 2 0 20 0 1 0 115954682 9433088 364 18446744073709551615 4194304 5129932 140734332211504 140734332210160 140377045550174 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6132/statm: 2303 364 303 229 0 63 0
[pid=6145] ppid=6132 vsize=51912 CPUtime=1.42
/proc/6145/stat : 6145 (cudf2lp) R 6132 6132 1750 0 -1 4202496 15038 0 0 0 136 6 0 0 20 0 1 0 115954685 53157888 11637 18446744073709551615 4194304 5690517 140734209567536 140734209565176 4247179 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/6145/statm: 12978 11637 160 366 0 12609 0
Current children cumulated CPU time (s) 1.44
Current children cumulated vsize (KiB) 61124

[startup+3.1002 s]
/proc/loadavg: 1.07 0.99 0.92 2/61 6145
/proc/meminfo: memFree=273040/1022884 swapFree=0/0
[pid=6132] ppid=6131 vsize=9212 CPUtime=2.45
/proc/6132/stat : 6132 (aspuncud-basic) S 6131 6132 1750 0 -1 4202496 719 26699 0 0 0 0 233 12 20 0 1 0 115954682 9433088 364 18446744073709551615 4194304 5129932 140734332211504 140734332210160 140377045550174 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6132/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 2.45
Current children cumulated vsize (KiB) 9212
heavy processes:

[startup+6.30026 s]
/proc/loadavg: 1.15 1.00 0.92 2/61 6146
/proc/meminfo: memFree=96464/1022884 swapFree=0/0
[pid=6132] ppid=6131 vsize=9212 CPUtime=2.45
/proc/6132/stat : 6132 (aspuncud-basic) S 6131 6132 1750 0 -1 4202496 719 26699 0 0 0 0 233 12 20 0 1 0 115954682 9433088 364 18446744073709551615 4194304 5129932 140734332211504 140734332210160 140377045550174 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6132/statm: 2303 364 303 229 0 63 0
[pid=6146] ppid=6132 vsize=383640 CPUtime=3.74
/proc/6146/stat : 6146 (gringo) R 6132 6132 1750 0 -1 4202496 89088 0 0 0 348 26 0 0 20 0 1 0 115954934 392847360 80321 18446744073709551615 4194304 6531320 140737163131520 140737163128136 5101273 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/6146/statm: 95910 80321 283 571 0 95331 0
Current children cumulated CPU time (s) 6.19
Current children cumulated vsize (KiB) 392852

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

[startup+6.40032 s]
/proc/loadavg: 1.15 1.00 0.92 2/61 6146
/proc/meminfo: memFree=96464/1022884 swapFree=0/0
[pid=6132] ppid=6131 vsize=9212 CPUtime=2.45
/proc/6132/stat : 6132 (aspuncud-basic) S 6131 6132 1750 0 -1 4202496 719 26699 0 0 0 0 233 12 20 0 1 0 115954682 9433088 364 18446744073709551615 4194304 5129932 140734332211504 140734332210160 140377045550174 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6132/statm: 2303 364 303 229 0 63 0
[pid=6146] ppid=6132 vsize=392124 CPUtime=3.83
/proc/6146/stat : 6146 (gringo) R 6132 6132 1750 0 -1 4202496 91028 0 0 0 357 26 0 0 20 0 1 0 115954934 401534976 82261 18446744073709551615 4194304 6531320 140737163131520 140737163128136 4315205 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/6146/statm: 98031 82261 283 571 0 97452 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 401336

[startup+8.00033 s]
/proc/loadavg: 1.15 1.00 0.92 2/62 6148
/proc/meminfo: memFree=239932/1022884 swapFree=0/0
[pid=6132] ppid=6131 vsize=9212 CPUtime=6.94
/proc/6132/stat : 6132 (aspuncud-basic) S 6131 6132 1750 0 -1 4202496 757 125163 0 0 0 0 644 50 20 0 1 0 115954682 9433088 364 18446744073709551615 4194304 5129932 140734332211504 140734332209568 140377045550174 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6132/statm: 2303 364 303 229 0 63 0
[pid=6147] ppid=6132 vsize=125416 CPUtime=0.86
/proc/6147/stat : 6147 (unclasp) R 6132 6132 1750 0 -1 4202496 36632 0 0 0 75 11 0 0 20 0 1 0 115955393 128425984 30680 18446744073709551615 4194304 6012874 140736876756672 140736876755992 4548913 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/6147/statm: 31354 30680 219 444 0 30902 0
[pid=6148] ppid=6132 vsize=22040 CPUtime=0.01
/proc/6148/stat : 6148 (parse.py) S 6132 6132 1750 0 -1 4202496 1310 0 8 0 0 1 0 0 20 0 1 0 115955393 22568960 1128 18446744073709551615 4194304 6642060 140735767824992 140735767823352 140180408993568 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/6148/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 7.81
Current children cumulated vsize (KiB) 156668

[startup+9.60032 s]
/proc/loadavg: 1.15 1.00 0.92 2/62 6148
/proc/meminfo: memFree=243032/1022884 swapFree=0/0
[pid=6132] ppid=6131 vsize=9212 CPUtime=6.94
/proc/6132/stat : 6132 (aspuncud-basic) S 6131 6132 1750 0 -1 4202496 757 125163 0 0 0 0 644 50 20 0 1 0 115954682 9433088 364 18446744073709551615 4194304 5129932 140734332211504 140734332209568 140377045550174 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6132/statm: 2303 364 303 229 0 63 0
[pid=6147] ppid=6132 vsize=125416 CPUtime=2.45
/proc/6147/stat : 6147 (unclasp) R 6132 6132 1750 0 -1 4202496 36651 0 0 0 234 11 0 0 20 0 1 0 115955393 128425984 30699 18446744073709551615 4194304 6012874 140736876756672 140736876755992 4548507 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/6147/statm: 31354 30699 226 444 0 30902 0
[pid=6148] ppid=6132 vsize=22040 CPUtime=0.01
/proc/6148/stat : 6148 (parse.py) S 6132 6132 1750 0 -1 4202496 1310 0 8 0 0 1 0 0 20 0 1 0 115955393 22568960 1128 18446744073709551615 4194304 6642060 140735767824992 140735767823352 140180408993568 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/6148/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 9.4
Current children cumulated vsize (KiB) 156668

[startup+10.0074 s]
/proc/loadavg: 1.15 1.00 0.92 2/62 6148
/proc/meminfo: memFree=243032/1022884 swapFree=0/0
[pid=6132] ppid=6131 vsize=9212 CPUtime=6.94
/proc/6132/stat : 6132 (aspuncud-basic) S 6131 6132 1750 0 -1 4202496 757 125163 0 0 0 0 644 50 20 0 1 0 115954682 9433088 364 18446744073709551615 4194304 5129932 140734332211504 140734332209568 140377045550174 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6132/statm: 2303 364 303 229 0 63 0
[pid=6147] ppid=6132 vsize=125416 CPUtime=2.85
/proc/6147/stat : 6147 (unclasp) R 6132 6132 1750 0 -1 4202496 36651 0 0 0 274 11 0 0 20 0 1 0 115955393 128425984 30699 18446744073709551615 4194304 6012874 140736876756672 140736876755992 4532853 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/6147/statm: 31354 30699 226 444 0 30902 0
[pid=6148] ppid=6132 vsize=22040 CPUtime=0.01
/proc/6148/stat : 6148 (parse.py) S 6132 6132 1750 0 -1 4202496 1310 0 8 0 0 1 0 0 20 0 1 0 115955393 22568960 1128 18446744073709551615 4194304 6642060 140735767824992 140735767823352 140180408993568 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/6148/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 9.8
Current children cumulated vsize (KiB) 156668

[startup+10.4003 s]
/proc/loadavg: 1.15 1.00 0.92 2/62 6148
/proc/meminfo: memFree=243032/1022884 swapFree=0/0
[pid=6132] ppid=6131 vsize=9212 CPUtime=10.15
/proc/6132/stat : 6132 (aspuncud-basic) S 6131 6132 1750 0 -1 4202496 793 163154 0 8 0 0 948 67 20 0 1 0 115954682 9433088 364 18446744073709551615 4194304 5129932 140734332211504 140734332209056 140377045550174 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/6132/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 10.15
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 10.4528
CPU time (s): 10.1726
CPU user time (s): 9.48459
CPU system time (s): 0.688043
CPU usage (%): 97.3196
Max. virtual memory (cumulated for all children) (KiB): 434504

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 9.48459
system time used= 0.688043
maximum resident set size= 358772
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 164178
page faults= 9
swaps= 0
block input operations= 41608
block output operations= 42632
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 205
involuntary context switches= 1242

runsolver used 0.020001 second user time and 0.044002 second system time

The end