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/adf7b774-9af8-11df-bc37-00163e46d37a.cudf.log.runsolver /home/competition/aspuncud-basic-1.7/aspuncud-basic /home/competition/data/real/adf7b774-9af8-11df-bc37-00163e46d37a.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspuncud-basic-1.7/embedded/real/adf7b774-9af8-11df-bc37-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: 1.01 0.97 0.91 2/59 23938
/proc/meminfo: memFree=393620/1022884 swapFree=0/0
[pid=23938] ppid=23937 vsize=1068 CPUtime=0
/proc/23938/stat : 23938 (aspuncud-basic) D 23937 23938 1733 0 -1 4194304 75 0 0 0 0 0 0 0 20 0 1 0 115969115 1093632 1 18446744073709551615 0 0 140733374282681 4294282272 4151596080 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/23938/statm: 267 1 0 0 0 28 0

[startup+0.107569 s]
/proc/loadavg: 1.01 0.97 0.91 2/59 23938
/proc/meminfo: memFree=393620/1022884 swapFree=0/0
[pid=23938] ppid=23937 vsize=9212 CPUtime=0.03
/proc/23938/stat : 23938 (aspuncud-basic) S 23937 23938 1733 0 -1 4202496 643 2268 2 5 0 0 3 0 20 0 1 0 115969115 9433088 365 18446744073709551615 4194304 5129932 140733374274208 140733374272864 139839508354142 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23938/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200328 s]
/proc/loadavg: 1.01 0.97 0.91 2/59 23938
/proc/meminfo: memFree=393620/1022884 swapFree=0/0
[pid=23938] ppid=23937 vsize=9212 CPUtime=0.05
/proc/23938/stat : 23938 (aspuncud-basic) S 23937 23938 1733 0 -1 4202496 694 2803 2 7 0 1 4 0 20 0 1 0 115969115 9433088 365 18446744073709551615 4194304 5129932 140733374274208 140733374272864 139839508354142 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23938/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.30032 s]
/proc/loadavg: 1.01 0.97 0.91 2/59 23938
/proc/meminfo: memFree=393620/1022884 swapFree=0/0
[pid=23938] ppid=23937 vsize=9212 CPUtime=0.05
/proc/23938/stat : 23938 (aspuncud-basic) S 23937 23938 1733 0 -1 4202496 694 2803 2 7 0 1 4 0 20 0 1 0 115969115 9433088 365 18446744073709551615 4194304 5129932 140733374274208 140733374272864 139839508354142 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23938/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700226 s]
/proc/loadavg: 1.01 0.97 0.91 2/59 23938
/proc/meminfo: memFree=393620/1022884 swapFree=0/0
[pid=23938] ppid=23937 vsize=9212 CPUtime=0.05
/proc/23938/stat : 23938 (aspuncud-basic) S 23937 23938 1733 0 -1 4202496 694 2803 2 7 0 1 4 0 20 0 1 0 115969115 9433088 365 18446744073709551615 4194304 5129932 140733374274208 140733374272864 139839508354142 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23938/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50026 s]
/proc/loadavg: 1.01 0.97 0.91 2/61 23951
/proc/meminfo: memFree=368300/1022884 swapFree=0/0
[pid=23938] ppid=23937 vsize=9212 CPUtime=0.05
/proc/23938/stat : 23938 (aspuncud-basic) S 23937 23938 1733 0 -1 4202496 694 2803 2 7 0 1 4 0 20 0 1 0 115969115 9433088 365 18446744073709551615 4194304 5129932 140733374274208 140733374272864 139839508354142 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23938/statm: 2303 365 303 229 0 63 0
[pid=23951] ppid=23938 vsize=50256 CPUtime=1.37
/proc/23951/stat : 23951 (cudf2lp) R 23938 23938 1733 0 -1 4202496 14146 0 0 0 131 6 0 0 20 0 1 0 115969126 51462144 10745 18446744073709551615 4194304 5690517 140733775653552 140733775651192 4962807 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/23951/statm: 12564 10745 160 366 0 12195 0
Current children cumulated CPU time (s) 1.42
Current children cumulated vsize (KiB) 59468

[startup+3.10025 s]
/proc/loadavg: 1.01 0.97 0.91 2/61 23952
/proc/meminfo: memFree=386652/1022884 swapFree=0/0
[pid=23938] ppid=23937 vsize=9212 CPUtime=2.11
/proc/23938/stat : 23938 (aspuncud-basic) S 23937 23938 1733 0 -1 4202496 721 25382 2 7 0 1 196 14 20 0 1 0 115969115 9433088 365 18446744073709551615 4194304 5129932 140733374274208 140733374272864 139839508354142 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23938/statm: 2303 365 303 229 0 63 0
[pid=23952] ppid=23938 vsize=67356 CPUtime=0.89
/proc/23952/stat : 23952 (gringo) R 23938 23938 1733 0 -1 4202496 17120 0 0 0 86 3 0 0 20 0 1 0 115969334 68972544 14499 18446744073709551615 4194304 6531320 140735441433216 140735441429832 5101054 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23952/statm: 16839 14499 282 571 0 16260 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 76568

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

[startup+3.20031 s]
/proc/loadavg: 1.01 0.97 0.91 2/61 23952
/proc/meminfo: memFree=386652/1022884 swapFree=0/0
[pid=23938] ppid=23937 vsize=9212 CPUtime=2.11
/proc/23938/stat : 23938 (aspuncud-basic) S 23937 23938 1733 0 -1 4202496 721 25382 2 7 0 1 196 14 20 0 1 0 115969115 9433088 365 18446744073709551615 4194304 5129932 140733374274208 140733374272864 139839508354142 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23938/statm: 2303 365 303 229 0 63 0
[pid=23952] ppid=23938 vsize=86976 CPUtime=1
/proc/23952/stat : 23952 (gringo) R 23938 23938 1733 0 -1 4202496 21457 0 0 0 95 5 0 0 20 0 1 0 115969334 89063424 18836 18446744073709551615 4194304 6531320 140735441433216 140735441429560 5511603 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23952/statm: 21744 18836 283 571 0 21165 0
Current children cumulated CPU time (s) 3.11
Current children cumulated vsize (KiB) 96188

[startup+4.00021 s]
/proc/loadavg: 1.01 0.97 0.91 2/61 23952
/proc/meminfo: memFree=291792/1022884 swapFree=0/0
[pid=23938] ppid=23937 vsize=9212 CPUtime=3.77
/proc/23938/stat : 23938 (aspuncud-basic) S 23937 23938 1733 0 -1 4202496 759 65951 2 7 0 1 346 30 20 0 1 0 115969115 9433088 365 18446744073709551615 4194304 5129932 140733374274208 140733374272272 139839508354142 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23938/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 3.77
Current children cumulated vsize (KiB) 9212

[startup+4.4002 s]
/proc/loadavg: 1.01 0.97 0.91 2/62 23954
/proc/meminfo: memFree=333696/1022884 swapFree=0/0
[pid=23938] ppid=23937 vsize=9212 CPUtime=3.77
/proc/23938/stat : 23938 (aspuncud-basic) S 23937 23938 1733 0 -1 4202496 759 65951 2 7 0 1 346 30 20 0 1 0 115969115 9433088 365 18446744073709551615 4194304 5129932 140733374274208 140733374272272 139839508354142 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23938/statm: 2303 365 303 229 0 63 0
[pid=23953] ppid=23938 vsize=48260 CPUtime=0.52
/proc/23953/stat : 23953 (unclasp) R 23938 23938 1733 0 -1 4202496 14183 0 0 0 48 4 0 0 20 0 1 0 115969501 49418240 11610 18446744073709551615 4194304 6012874 140735086261024 140735086260344 4533443 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23953/statm: 12065 11610 226 444 0 11613 0
[pid=23954] ppid=23938 vsize=22044 CPUtime=0
/proc/23954/stat : 23954 (parse.py) S 23938 23938 1733 0 -1 4202496 1322 0 0 0 0 0 0 0 20 0 1 0 115969501 22573056 1131 18446744073709551615 4194304 6642060 140736300587344 140736300585544 140670839797536 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23954/statm: 5511 1131 508 598 0 597 0
Current children cumulated CPU time (s) 4.29
Current children cumulated vsize (KiB) 79516

[startup+4.60035 s]
/proc/loadavg: 1.01 0.97 0.91 2/62 23954
/proc/meminfo: memFree=333696/1022884 swapFree=0/0
[pid=23938] ppid=23937 vsize=9212 CPUtime=3.77
/proc/23938/stat : 23938 (aspuncud-basic) S 23937 23938 1733 0 -1 4202496 759 65951 2 7 0 1 346 30 20 0 1 0 115969115 9433088 365 18446744073709551615 4194304 5129932 140733374274208 140733374272272 139839508354142 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/23938/statm: 2303 365 303 229 0 63 0
[pid=23953] ppid=23938 vsize=48260 CPUtime=0.72
/proc/23953/stat : 23953 (unclasp) R 23938 23938 1733 0 -1 4202496 14183 0 0 0 68 4 0 0 20 0 1 0 115969501 49418240 11610 18446744073709551615 4194304 6012874 140735086261024 140735086260344 4548198 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23953/statm: 12065 11610 226 444 0 11613 0
[pid=23954] ppid=23938 vsize=22044 CPUtime=0
/proc/23954/stat : 23954 (parse.py) S 23938 23938 1733 0 -1 4202496 1322 0 0 0 0 0 0 0 20 0 1 0 115969501 22573056 1131 18446744073709551615 4194304 6642060 140736300587344 140736300585544 140670839797536 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23954/statm: 5511 1131 508 598 0 597 0
Current children cumulated CPU time (s) 4.49
Current children cumulated vsize (KiB) 79516

Child status: 0
Real time (s): 4.6698
CPU time (s): 4.58429
CPU user time (s): 4.20826
CPU system time (s): 0.376023
CPU usage (%): 98.1688
Max. virtual memory (cumulated for all children) (KiB): 178808

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.20826
system time used= 0.376023
maximum resident set size= 143580
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 82531
page faults= 9
swaps= 0
block input operations= 536
block output operations= 20312
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 81
involuntary context switches= 564

runsolver used 0.016001 second user time and 0.016001 second system time

The end