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/0207e19a-9b1c-11df-af69-00163e46d37a.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/real/0207e19a-9b1c-11df-af69-00163e46d37a.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/slowlink/real/0207e19a-9b1c-11df-af69-00163e46d37a.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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.01 0.98 0.96 2/56 27837
/proc/meminfo: memFree=365268/1022884 swapFree=0/0
[pid=27837] ppid=27836 vsize=9204 CPUtime=0
/proc/27837/stat : 27837 (aspuncud-full) S 27836 27837 32685 0 -1 4202496 433 0 0 0 0 0 0 0 20 0 1 0 42402936 9424896 332 18446744073709551615 4194304 5129932 140734846982912 140734846980376 140199101265696 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/27837/statm: 2301 332 272 229 0 61 0

[startup+0.13895 s]
/proc/loadavg: 1.01 0.98 0.96 2/56 27837
/proc/meminfo: memFree=365268/1022884 swapFree=0/0
[pid=27837] ppid=27836 vsize=9212 CPUtime=0.05
/proc/27837/stat : 27837 (aspuncud-full) S 27836 27837 32685 0 -1 4202496 698 2813 0 0 1 0 2 2 20 0 1 0 42402936 9433088 365 18446744073709551615 4194304 5129932 140734846982912 140734846981568 140199101121630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27837/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200285 s]
/proc/loadavg: 1.01 0.98 0.96 2/56 27837
/proc/meminfo: memFree=365268/1022884 swapFree=0/0
[pid=27837] ppid=27836 vsize=9212 CPUtime=0.05
/proc/27837/stat : 27837 (aspuncud-full) S 27836 27837 32685 0 -1 4202496 698 2813 0 0 1 0 2 2 20 0 1 0 42402936 9433088 365 18446744073709551615 4194304 5129932 140734846982912 140734846981568 140199101121630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27837/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300337 s]
/proc/loadavg: 1.01 0.98 0.96 2/56 27837
/proc/meminfo: memFree=365268/1022884 swapFree=0/0
[pid=27837] ppid=27836 vsize=9212 CPUtime=0.05
/proc/27837/stat : 27837 (aspuncud-full) S 27836 27837 32685 0 -1 4202496 698 2813 0 0 1 0 2 2 20 0 1 0 42402936 9433088 365 18446744073709551615 4194304 5129932 140734846982912 140734846981568 140199101121630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27837/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700234 s]
/proc/loadavg: 1.01 0.98 0.96 2/56 27837
/proc/meminfo: memFree=365268/1022884 swapFree=0/0
[pid=27837] ppid=27836 vsize=9212 CPUtime=0.05
/proc/27837/stat : 27837 (aspuncud-full) S 27836 27837 32685 0 -1 4202496 698 2813 0 0 1 0 2 2 20 0 1 0 42402936 9433088 365 18446744073709551615 4194304 5129932 140734846982912 140734846981568 140199101121630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27837/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50025 s]
/proc/loadavg: 1.01 0.98 0.96 1/58 27850
/proc/meminfo: memFree=330772/1022884 swapFree=0/0
[pid=27837] ppid=27836 vsize=9212 CPUtime=0.05
/proc/27837/stat : 27837 (aspuncud-full) S 27836 27837 32685 0 -1 4202496 698 2813 0 0 1 0 2 2 20 0 1 0 42402936 9433088 365 18446744073709551615 4194304 5129932 140734846982912 140734846981568 140199101121630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27837/statm: 2303 365 303 229 0 63 0
[pid=27850] ppid=27837 vsize=50252 CPUtime=1.24
/proc/27850/stat : 27850 (cudf2lp) R 27837 27837 32685 0 -1 4202496 14060 0 0 0 120 4 0 0 20 0 1 0 42402940 51458048 10662 18446744073709551615 4194304 5690517 140735254341376 140735254339016 4293705 0 0 16781316 0 0 0 0 17 0 0 0 21 0 0
/proc/27850/statm: 12563 10662 160 366 0 12194 0
Current children cumulated CPU time (s) 1.29
Current children cumulated vsize (KiB) 59464

[startup+3.10023 s]
/proc/loadavg: 1.01 0.98 0.96 2/58 27850
/proc/meminfo: memFree=269888/1022884 swapFree=0/0
[pid=27837] ppid=27836 vsize=9212 CPUtime=2.33
/proc/27837/stat : 27837 (aspuncud-full) S 27836 27837 32685 0 -1 4202496 725 25392 0 0 1 0 218 14 20 0 1 0 42402936 9433088 365 18446744073709551615 4194304 5129932 140734846982912 140734846981568 140199101121630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27837/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 2.33
Current children cumulated vsize (KiB) 9212
heavy processes:

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

[startup+3.20873 s]
/proc/loadavg: 1.01 0.98 0.96 2/58 27851
/proc/meminfo: memFree=325812/1022884 swapFree=0/0
[pid=27837] ppid=27836 vsize=9212 CPUtime=2.33
/proc/27837/stat : 27837 (aspuncud-full) S 27836 27837 32685 0 -1 4202496 725 25392 0 0 1 0 218 14 20 0 1 0 42402936 9433088 365 18446744073709551615 4194304 5129932 140734846982912 140734846981568 140199101121630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27837/statm: 2303 365 303 229 0 63 0
[pid=27851] ppid=27837 vsize=21544 CPUtime=0.64
/proc/27851/stat : 27851 (gringo) R 27837 27837 32685 0 -1 4202496 5902 0 0 0 60 4 0 0 20 0 1 0 42403192 22061056 4307 18446744073709551615 4194304 6531320 140733933013552 140733933010168 5484576 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/27851/statm: 5386 4307 259 571 0 4807 0
Current children cumulated CPU time (s) 2.97
Current children cumulated vsize (KiB) 30756

[startup+4.00027 s]
/proc/loadavg: 1.01 0.98 0.96 2/58 27851
/proc/meminfo: memFree=321348/1022884 swapFree=0/0
[pid=27837] ppid=27836 vsize=9212 CPUtime=2.33
/proc/27837/stat : 27837 (aspuncud-full) S 27836 27837 32685 0 -1 4202496 725 25392 0 0 1 0 218 14 20 0 1 0 42402936 9433088 365 18446744073709551615 4194304 5129932 140734846982912 140734846981568 140199101121630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27837/statm: 2303 365 303 229 0 63 0
[pid=27851] ppid=27837 vsize=94160 CPUtime=1.43
/proc/27851/stat : 27851 (gringo) R 27837 27837 32685 0 -1 4202496 22968 0 0 0 133 10 0 0 20 0 1 0 42403192 96419840 20348 18446744073709551615 4194304 6531320 140733933013552 140733933009896 5554591 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/27851/statm: 23540 20348 283 571 0 22961 0
Current children cumulated CPU time (s) 3.76
Current children cumulated vsize (KiB) 103372

[startup+4.8002 s]
/proc/loadavg: 1.01 0.98 0.96 2/58 27851
/proc/meminfo: memFree=203424/1022884 swapFree=0/0
[pid=27837] ppid=27836 vsize=9212 CPUtime=4.44
/proc/27837/stat : 27837 (aspuncud-full) S 27836 27837 32685 0 -1 4202496 764 66647 0 0 1 0 407 36 20 0 1 0 42402936 9433088 365 18446744073709551615 4194304 5129932 140734846982912 140734846980976 140199101121630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27837/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 4.44
Current children cumulated vsize (KiB) 9212

[startup+5.00099 s]
/proc/loadavg: 1.01 0.98 0.96 2/58 27851
/proc/meminfo: memFree=203424/1022884 swapFree=0/0
[pid=27837] ppid=27836 vsize=9212 CPUtime=4.44
/proc/27837/stat : 27837 (aspuncud-full) S 27836 27837 32685 0 -1 4202496 764 66647 0 0 1 0 407 36 20 0 1 0 42402936 9433088 365 18446744073709551615 4194304 5129932 140734846982912 140734846980976 140199101121630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27837/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 4.44
Current children cumulated vsize (KiB) 9212

[startup+5.1002 s]
/proc/loadavg: 1.01 0.98 0.96 2/58 27851
/proc/meminfo: memFree=203424/1022884 swapFree=0/0
[pid=27837] ppid=27836 vsize=9212 CPUtime=4.77
/proc/27837/stat : 27837 (aspuncud-full) S 27836 27837 32685 0 -1 4202496 799 82449 0 0 1 0 434 42 20 0 1 0 42402936 9433088 365 18446744073709551615 4194304 5129932 140734846982912 140734846980464 140199101121630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/27837/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 4.77
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 5.12179
CPU time (s): 4.7843
CPU user time (s): 4.35627
CPU system time (s): 0.428026
CPU usage (%): 93.4107
Max. virtual memory (cumulated for all children) (KiB): 181452

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.35627
system time used= 0.428026
maximum resident set size= 146328
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 83481
page faults= 0
swaps= 0
block input operations= 37880
block output operations= 20672
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 165
involuntary context switches= 121

runsolver used 0.020001 second user time and 0.024001 second system time

The end