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/7bf50d1c-9b1b-11df-8b50-00163e46d37a.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/real/7bf50d1c-9b1b-11df-8b50-00163e46d37a.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/slowlink/real/7bf50d1c-9b1b-11df-8b50-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.00 1.01 1.00 2/64 21224
/proc/meminfo: memFree=392208/1022884 swapFree=0/0
[pid=21224] ppid=21223 vsize=9180 CPUtime=0
/proc/21224/stat : 21224 (aspuncud-full) R 21223 21224 1745 0 -1 4202496 409 0 0 0 0 0 0 0 20 0 1 0 120633377 9400320 316 18446744073709551615 4194304 5129932 140734350048176 140734350043224 139648283280571 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/21224/statm: 2295 316 263 229 0 55 0

[startup+0.129443 s]
/proc/loadavg: 1.00 1.01 1.00 2/64 21224
/proc/meminfo: memFree=392208/1022884 swapFree=0/0
[pid=21224] ppid=21223 vsize=9212 CPUtime=0.03
/proc/21224/stat : 21224 (aspuncud-full) S 21223 21224 1745 0 -1 4202496 697 2811 0 0 0 0 2 1 20 0 1 0 120633377 9433088 364 18446744073709551615 4194304 5129932 140734350048176 140734350046832 139648283821150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21224/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200336 s]
/proc/loadavg: 1.00 1.01 1.00 2/64 21224
/proc/meminfo: memFree=392208/1022884 swapFree=0/0
[pid=21224] ppid=21223 vsize=9212 CPUtime=0.03
/proc/21224/stat : 21224 (aspuncud-full) S 21223 21224 1745 0 -1 4202496 697 2811 0 0 0 0 2 1 20 0 1 0 120633377 9433088 364 18446744073709551615 4194304 5129932 140734350048176 140734350046832 139648283821150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21224/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300338 s]
/proc/loadavg: 1.00 1.01 1.00 2/64 21224
/proc/meminfo: memFree=392208/1022884 swapFree=0/0
[pid=21224] ppid=21223 vsize=9212 CPUtime=0.03
/proc/21224/stat : 21224 (aspuncud-full) S 21223 21224 1745 0 -1 4202496 697 2811 0 0 0 0 2 1 20 0 1 0 120633377 9433088 364 18446744073709551615 4194304 5129932 140734350048176 140734350046832 139648283821150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21224/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700208 s]
/proc/loadavg: 1.00 1.01 1.00 2/64 21224
/proc/meminfo: memFree=392208/1022884 swapFree=0/0
[pid=21224] ppid=21223 vsize=9212 CPUtime=0.03
/proc/21224/stat : 21224 (aspuncud-full) S 21223 21224 1745 0 -1 4202496 697 2811 0 0 0 0 2 1 20 0 1 0 120633377 9433088 364 18446744073709551615 4194304 5129932 140734350048176 140734350046832 139648283821150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21224/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50034 s]
/proc/loadavg: 1.00 1.01 1.00 2/66 21237
/proc/meminfo: memFree=352388/1022884 swapFree=0/0
[pid=21224] ppid=21223 vsize=9212 CPUtime=0.03
/proc/21224/stat : 21224 (aspuncud-full) S 21223 21224 1745 0 -1 4202496 697 2811 0 0 0 0 2 1 20 0 1 0 120633377 9433088 364 18446744073709551615 4194304 5129932 140734350048176 140734350046832 139648283821150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21224/statm: 2303 364 303 229 0 63 0
[pid=21237] ppid=21224 vsize=50216 CPUtime=1.36
/proc/21237/stat : 21237 (cudf2lp) R 21224 21224 1745 0 -1 4202496 14295 0 0 0 131 5 0 0 20 0 1 0 120633380 51421184 10897 18446744073709551615 4194304 5690517 140733716201872 140733716199512 4373359 0 0 16781316 0 0 0 0 17 0 0 0 9 0 0
/proc/21237/statm: 12554 10897 160 366 0 12185 0
Current children cumulated CPU time (s) 1.39
Current children cumulated vsize (KiB) 59428

[startup+3.10024 s]
/proc/loadavg: 1.00 1.01 1.00 2/66 21237
/proc/meminfo: memFree=298820/1022884 swapFree=0/0
[pid=21224] ppid=21223 vsize=9212 CPUtime=2.3
/proc/21224/stat : 21224 (aspuncud-full) S 21223 21224 1745 0 -1 4202496 724 25387 0 0 0 0 216 14 20 0 1 0 120633377 9433088 364 18446744073709551615 4194304 5129932 140734350048176 140734350046832 139648283821150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21224/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 2.3
Current children cumulated vsize (KiB) 9212
heavy processes:

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

[startup+3.2053 s]
/proc/loadavg: 1.00 1.01 1.00 2/66 21238
/proc/meminfo: memFree=354868/1022884 swapFree=0/0
[pid=21224] ppid=21223 vsize=9212 CPUtime=2.3
/proc/21224/stat : 21224 (aspuncud-full) S 21223 21224 1745 0 -1 4202496 724 25387 0 0 0 0 216 14 20 0 1 0 120633377 9433088 364 18446744073709551615 4194304 5129932 140734350048176 140734350046832 139648283821150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21224/statm: 2303 364 303 229 0 63 0
[pid=21238] ppid=21224 vsize=18036 CPUtime=0.59
/proc/21238/stat : 21238 (gringo) R 21224 21224 1745 0 -1 4202496 4943 0 0 0 59 0 0 0 20 0 1 0 120633637 18468864 3861 18446744073709551615 4194304 6531320 140733503588512 140733503584328 4420311 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21238/statm: 4509 3861 259 571 0 3930 0
Current children cumulated CPU time (s) 2.89
Current children cumulated vsize (KiB) 27248

[startup+4.00025 s]
/proc/loadavg: 1.00 1.01 1.00 2/66 21238
/proc/meminfo: memFree=350528/1022884 swapFree=0/0
[pid=21224] ppid=21223 vsize=9212 CPUtime=2.3
/proc/21224/stat : 21224 (aspuncud-full) S 21223 21224 1745 0 -1 4202496 724 25387 0 0 0 0 216 14 20 0 1 0 120633377 9433088 364 18446744073709551615 4194304 5129932 140734350048176 140734350046832 139648283821150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21224/statm: 2303 364 303 229 0 63 0
[pid=21238] ppid=21224 vsize=76408 CPUtime=1.38
/proc/21238/stat : 21238 (gringo) R 21224 21224 1745 0 -1 4202496 19352 0 0 0 133 5 0 0 20 0 1 0 120633637 78241792 16732 18446744073709551615 4194304 6531320 140733503588512 140733503584792 4596926 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21238/statm: 19102 16732 282 571 0 18523 0
Current children cumulated CPU time (s) 3.68
Current children cumulated vsize (KiB) 85620

[startup+4.40025 s]
/proc/loadavg: 1.00 1.01 1.00 2/66 21238
/proc/meminfo: memFree=242028/1022884 swapFree=0/0
[pid=21224] ppid=21223 vsize=9212 CPUtime=2.3
/proc/21224/stat : 21224 (aspuncud-full) S 21223 21224 1745 0 -1 4202496 724 25387 0 0 0 0 216 14 20 0 1 0 120633377 9433088 364 18446744073709551615 4194304 5129932 140734350048176 140734350046832 139648283821150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21224/statm: 2303 364 303 229 0 63 0
[pid=21238] ppid=21224 vsize=146144 CPUtime=1.79
/proc/21238/stat : 21238 (gringo) R 21224 21224 1745 0 -1 4202496 35410 0 0 0 170 9 0 0 20 0 1 0 120633637 149651456 30741 18446744073709551615 4194304 6531320 140733503588512 140733503584856 4598430 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21238/statm: 36536 30741 283 571 0 35957 0
Current children cumulated CPU time (s) 4.09
Current children cumulated vsize (KiB) 155356

[startup+4.80021 s]
/proc/loadavg: 1.00 1.01 1.00 2/66 21238
/proc/meminfo: memFree=242028/1022884 swapFree=0/0
[pid=21224] ppid=21223 vsize=9212 CPUtime=4.34
/proc/21224/stat : 21224 (aspuncud-full) S 21223 21224 1745 0 -1 4202496 763 63596 0 0 0 0 406 28 20 0 1 0 120633377 9433088 364 18446744073709551615 4194304 5129932 140734350048176 140734350046240 139648283821150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21224/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 4.34
Current children cumulated vsize (KiB) 9212

[startup+4.90019 s]
/proc/loadavg: 1.00 1.01 1.00 2/66 21238
/proc/meminfo: memFree=242028/1022884 swapFree=0/0
[pid=21224] ppid=21223 vsize=9212 CPUtime=4.34
/proc/21224/stat : 21224 (aspuncud-full) S 21223 21224 1745 0 -1 4202496 763 63596 0 0 0 0 406 28 20 0 1 0 120633377 9433088 364 18446744073709551615 4194304 5129932 140734350048176 140734350046240 139648283821150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21224/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 4.34
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 4.96032
CPU time (s): 4.65229
CPU user time (s): 4.29627
CPU system time (s): 0.356022
CPU usage (%): 93.7901
Max. virtual memory (cumulated for all children) (KiB): 167404

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.29627
system time used= 0.356022
maximum resident set size= 134144
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 79187
page faults= 0
swaps= 0
block input operations= 37872
block output operations= 19328
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 91
involuntary context switches= 574

runsolver used 0.016001 second user time and 0.024001 second system time

The end