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 300 -d 10 -w /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/slowlink/real/ff4a1d84-d490-11df-9e6c-00163e3d3b7c.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/real/ff4a1d84-d490-11df-9e6c-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/slowlink/real/ff4a1d84-d490-11df-9e6c-00163e3d3b7c.cudf.result -sum(changed,installedsize),-count(removed),-notuptodate(solution),-count(changed) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 300 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 330 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.04 0.98 0.96 2/56 27705
/proc/meminfo: memFree=327480/1022884 swapFree=0/0
[pid=27705] ppid=27704 vsize=3152 CPUtime=0
/proc/27705/stat : 27705 (runsolver) R 27704 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 42396803 3227648 32 18446744073709551615 134512640 134586868 4287468608 4287466656 4152087600 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/27705/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.165641 s]
/proc/loadavg: 1.04 0.98 0.96 2/56 27705
/proc/meminfo: memFree=327480/1022884 swapFree=0/0
[pid=27705] ppid=27704 vsize=9212 CPUtime=0.02
/proc/27705/stat : 27705 (aspuncud-full) S 27704 27705 32685 0 -1 4202496 702 2805 0 0 0 0 2 0 20 0 1 0 42396803 9433088 365 18446744073709551615 4194304 5129932 140733826687680 140733826686336 140172762367070 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27705/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200332 s]
/proc/loadavg: 1.04 0.98 0.96 2/56 27705
/proc/meminfo: memFree=327480/1022884 swapFree=0/0
[pid=27705] ppid=27704 vsize=9212 CPUtime=0.02
/proc/27705/stat : 27705 (aspuncud-full) S 27704 27705 32685 0 -1 4202496 702 2805 0 0 0 0 2 0 20 0 1 0 42396803 9433088 365 18446744073709551615 4194304 5129932 140733826687680 140733826686336 140172762367070 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27705/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300309 s]
/proc/loadavg: 1.04 0.98 0.96 2/56 27705
/proc/meminfo: memFree=327480/1022884 swapFree=0/0
[pid=27705] ppid=27704 vsize=9212 CPUtime=0.02
/proc/27705/stat : 27705 (aspuncud-full) S 27704 27705 32685 0 -1 4202496 702 2805 0 0 0 0 2 0 20 0 1 0 42396803 9433088 365 18446744073709551615 4194304 5129932 140733826687680 140733826686336 140172762367070 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27705/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700205 s]
/proc/loadavg: 1.04 0.98 0.96 2/56 27705
/proc/meminfo: memFree=327480/1022884 swapFree=0/0
[pid=27705] ppid=27704 vsize=9212 CPUtime=0.02
/proc/27705/stat : 27705 (aspuncud-full) S 27704 27705 32685 0 -1 4202496 702 2805 0 0 0 0 2 0 20 0 1 0 42396803 9433088 365 18446744073709551615 4194304 5129932 140733826687680 140733826686336 140172762367070 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27705/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50035 s]
/proc/loadavg: 1.04 0.98 0.96 2/58 27718
/proc/meminfo: memFree=286536/1022884 swapFree=0/0
[pid=27705] ppid=27704 vsize=9212 CPUtime=0.02
/proc/27705/stat : 27705 (aspuncud-full) S 27704 27705 32685 0 -1 4202496 702 2805 0 0 0 0 2 0 20 0 1 0 42396803 9433088 365 18446744073709551615 4194304 5129932 140733826687680 140733826686336 140172762367070 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27705/statm: 2303 365 303 229 0 63 0
[pid=27718] ppid=27705 vsize=51240 CPUtime=1.39
/proc/27718/stat : 27718 (cudf2lp) R 27705 27705 32685 0 -1 4202496 14649 0 0 0 131 8 0 0 20 0 1 0 42396806 52469760 11251 18446744073709551615 4194304 5690517 140734649279808 140734649277480 5058400 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/27718/statm: 12810 11251 160 366 0 12441 0
Current children cumulated CPU time (s) 1.41
Current children cumulated vsize (KiB) 60452

[startup+3.10023 s]
/proc/loadavg: 1.04 0.98 0.96 2/58 27718
/proc/meminfo: memFree=229496/1022884 swapFree=0/0
[pid=27705] ppid=27704 vsize=9212 CPUtime=2.75
/proc/27705/stat : 27705 (aspuncud-full) S 27704 27705 32685 0 -1 4202496 730 27752 0 0 0 0 256 19 20 0 1 0 42396803 9433088 365 18446744073709551615 4194304 5129932 140733826687680 140733826686336 140172762367070 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27705/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 2.75
Current children cumulated vsize (KiB) 9212

[startup+6.30026 s]
/proc/loadavg: 1.04 0.98 0.96 2/58 27719
/proc/meminfo: memFree=178136/1022884 swapFree=0/0
[pid=27705] ppid=27704 vsize=9212 CPUtime=2.75
/proc/27705/stat : 27705 (aspuncud-full) S 27704 27705 32685 0 -1 4202496 730 27752 0 0 0 0 256 19 20 0 1 0 42396803 9433088 365 18446744073709551615 4194304 5129932 140733826687680 140733826686336 140172762367070 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27705/statm: 2303 365 303 229 0 63 0
[pid=27719] ppid=27705 vsize=240660 CPUtime=3.43
/proc/27719/stat : 27719 (gringo) R 27705 27705 32685 0 -1 4202496 58627 0 0 0 321 22 0 0 20 0 1 0 42397088 246435840 49861 18446744073709551615 4194304 6531320 140736370178096 140736370174712 4315040 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/27719/statm: 60165 49861 283 571 0 59586 0
Current children cumulated CPU time (s) 6.18
Current children cumulated vsize (KiB) 249872

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

[startup+6.40032 s]
/proc/loadavg: 1.04 0.98 0.96 2/58 27719
/proc/meminfo: memFree=178136/1022884 swapFree=0/0
[pid=27705] ppid=27704 vsize=9212 CPUtime=2.75
/proc/27705/stat : 27705 (aspuncud-full) S 27704 27705 32685 0 -1 4202496 730 27752 0 0 0 0 256 19 20 0 1 0 42396803 9433088 365 18446744073709551615 4194304 5129932 140733826687680 140733826686336 140172762367070 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27705/statm: 2303 365 303 229 0 63 0
[pid=27719] ppid=27705 vsize=257080 CPUtime=3.52
/proc/27719/stat : 27719 (gringo) R 27705 27705 32685 0 -1 4202496 62305 0 0 0 329 23 0 0 20 0 1 0 42397088 263249920 53539 18446744073709551615 4194304 6531320 140736370178096 140736370174088 5563228 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/27719/statm: 64270 53539 283 571 0 63691 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 266292

[startup+8.00019 s]
/proc/loadavg: 1.03 0.98 0.96 2/58 27719
/proc/meminfo: memFree=33864/1022884 swapFree=0/0
[pid=27705] ppid=27704 vsize=9212 CPUtime=7.59
/proc/27705/stat : 27705 (aspuncud-full) S 27704 27705 32685 0 -1 4202496 770 115998 0 0 0 0 703 56 20 0 1 0 42396803 9433088 365 18446744073709551615 4194304 5129932 140733826687680 140733826685744 140172762367070 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27705/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 7.59
Current children cumulated vsize (KiB) 9212

[startup+8.4002 s]
/proc/loadavg: 1.03 0.98 0.96 2/58 27719
/proc/meminfo: memFree=33864/1022884 swapFree=0/0
[pid=27705] ppid=27704 vsize=9212 CPUtime=7.59
/proc/27705/stat : 27705 (aspuncud-full) S 27704 27705 32685 0 -1 4202496 770 115998 0 0 0 0 703 56 20 0 1 0 42396803 9433088 365 18446744073709551615 4194304 5129932 140733826687680 140733826685744 140172762367070 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27705/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 7.59
Current children cumulated vsize (KiB) 9212

[startup+8.60082 s]
/proc/loadavg: 1.03 0.98 0.96 2/58 27719
/proc/meminfo: memFree=33864/1022884 swapFree=0/0
[pid=27705] ppid=27704 vsize=9212 CPUtime=7.59
/proc/27705/stat : 27705 (aspuncud-full) S 27704 27705 32685 0 -1 4202496 770 115998 0 0 0 0 703 56 20 0 1 0 42396803 9433088 365 18446744073709551615 4194304 5129932 140733826687680 140733826685744 140172762367070 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27705/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 7.59
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 8.63443
CPU time (s): 8.46453
CPU user time (s): 7.77248
CPU system time (s): 0.692043
CPU usage (%): 98.0323
Max. virtual memory (cumulated for all children) (KiB): 381900

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.77248
system time used= 0.692043
maximum resident set size= 317904
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 151006
page faults= 0
swaps= 0
block input operations= 43024
block output operations= 39080
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 161
involuntary context switches= 279

runsolver used 0.012 second user time and 0.040002 second system time

The end