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/aspcud-full-1.7/slowlink/real/dba3a3fe-3477-11e0-9e6c-00163e3d3b7c.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/real/dba3a3fe-3477-11e0-9e6c-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/slowlink/real/dba3a3fe-3477-11e0-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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 0.92 0.97 0.98 2/64 19711
/proc/meminfo: memFree=409720/1022884 swapFree=0/0
[pid=19711] ppid=19710 vsize=9204 CPUtime=0
/proc/19711/stat : 19711 (aspcud-full) S 19710 19711 1745 0 -1 4202496 430 0 0 0 0 0 0 0 20 0 1 0 120184437 9424896 331 18446744073709551615 4194304 5129932 140733906466128 140733906463592 139868695926560 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/19711/statm: 2301 331 272 229 0 61 0

[startup+0.196174 s]
/proc/loadavg: 0.92 0.97 0.98 2/64 19711
/proc/meminfo: memFree=409720/1022884 swapFree=0/0
[pid=19711] ppid=19710 vsize=9212 CPUtime=0.03
/proc/19711/stat : 19711 (aspcud-full) S 19710 19711 1745 0 -1 4202496 739 3623 0 0 0 0 2 1 20 0 1 0 120184437 9433088 364 18446744073709551615 4194304 5129932 140733906466128 140733906464784 139868695782494 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19711/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200272 s]
/proc/loadavg: 0.92 0.97 0.98 2/64 19711
/proc/meminfo: memFree=409720/1022884 swapFree=0/0
[pid=19711] ppid=19710 vsize=9212 CPUtime=0.03
/proc/19711/stat : 19711 (aspcud-full) S 19710 19711 1745 0 -1 4202496 739 3623 0 0 0 0 2 1 20 0 1 0 120184437 9433088 364 18446744073709551615 4194304 5129932 140733906466128 140733906464784 139868695782494 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19711/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.30022 s]
/proc/loadavg: 0.92 0.97 0.98 2/64 19711
/proc/meminfo: memFree=409720/1022884 swapFree=0/0
[pid=19711] ppid=19710 vsize=9212 CPUtime=0.03
/proc/19711/stat : 19711 (aspcud-full) S 19710 19711 1745 0 -1 4202496 739 3623 0 0 0 0 2 1 20 0 1 0 120184437 9433088 364 18446744073709551615 4194304 5129932 140733906466128 140733906464784 139868695782494 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19711/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700252 s]
/proc/loadavg: 0.92 0.97 0.98 2/64 19711
/proc/meminfo: memFree=409720/1022884 swapFree=0/0
[pid=19711] ppid=19710 vsize=9212 CPUtime=0.03
/proc/19711/stat : 19711 (aspcud-full) S 19710 19711 1745 0 -1 4202496 739 3623 0 0 0 0 2 1 20 0 1 0 120184437 9433088 364 18446744073709551615 4194304 5129932 140733906466128 140733906464784 139868695782494 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19711/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.92 0.97 0.98 2/66 19727
/proc/meminfo: memFree=372372/1022884 swapFree=0/0
[pid=19711] ppid=19710 vsize=9212 CPUtime=0.03
/proc/19711/stat : 19711 (aspcud-full) S 19710 19711 1745 0 -1 4202496 739 3623 0 0 0 0 2 1 20 0 1 0 120184437 9433088 364 18446744073709551615 4194304 5129932 140733906466128 140733906464784 139868695782494 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19711/statm: 2303 364 303 229 0 63 0
[pid=19727] ppid=19711 vsize=50504 CPUtime=1.44
/proc/19727/stat : 19727 (cudf2lp) R 19711 19711 1745 0 -1 4202496 14211 0 0 0 139 5 0 0 20 0 1 0 120184440 51716096 10811 18446744073709551615 4194304 5690517 140734115746496 140734115744136 4293666 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/19727/statm: 12626 10811 160 366 0 12257 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 59716

[startup+3.10032 s]
/proc/loadavg: 0.93 0.97 0.98 2/66 19728
/proc/meminfo: memFree=385144/1022884 swapFree=0/0
[pid=19711] ppid=19710 vsize=9212 CPUtime=2.01
/proc/19711/stat : 19711 (aspcud-full) S 19710 19711 1745 0 -1 4202496 763 22465 0 0 0 0 190 11 20 0 1 0 120184437 9433088 364 18446744073709551615 4194304 5129932 140733906466128 140733906464784 139868695782494 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19711/statm: 2303 364 303 229 0 63 0
[pid=19728] ppid=19711 vsize=51832 CPUtime=1.04
/proc/19728/stat : 19728 (gringo) R 19711 19711 1745 0 -1 4202496 12981 0 0 0 96 8 0 0 20 0 1 0 120184642 53075968 10360 18446744073709551615 4194304 6531320 140734578593312 140734578589928 4358974 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/19728/statm: 12958 10360 280 571 0 12379 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 61044

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

[startup+3.20038 s]
/proc/loadavg: 0.93 0.97 0.98 2/66 19728
/proc/meminfo: memFree=385144/1022884 swapFree=0/0
[pid=19711] ppid=19710 vsize=9212 CPUtime=2.01
/proc/19711/stat : 19711 (aspcud-full) S 19710 19711 1745 0 -1 4202496 763 22465 0 0 0 0 190 11 20 0 1 0 120184437 9433088 364 18446744073709551615 4194304 5129932 140733906466128 140733906464784 139868695782494 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19711/statm: 2303 364 303 229 0 63 0
[pid=19728] ppid=19711 vsize=53628 CPUtime=1.14
/proc/19728/stat : 19728 (gringo) R 19711 19711 1745 0 -1 4202496 13510 0 0 0 106 8 0 0 20 0 1 0 120184642 54915072 10889 18446744073709551615 4194304 6531320 140734578593312 140734578589928 5510966 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/19728/statm: 13407 10889 280 571 0 12828 0
Current children cumulated CPU time (s) 3.15
Current children cumulated vsize (KiB) 62840

[startup+4.00031 s]
/proc/loadavg: 0.93 0.97 0.98 2/66 19728
/proc/meminfo: memFree=341248/1022884 swapFree=0/0
[pid=19711] ppid=19710 vsize=9212 CPUtime=2.01
/proc/19711/stat : 19711 (aspcud-full) S 19710 19711 1745 0 -1 4202496 763 22465 0 0 0 0 190 11 20 0 1 0 120184437 9433088 364 18446744073709551615 4194304 5129932 140733906466128 140733906464784 139868695782494 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19711/statm: 2303 364 303 229 0 63 0
[pid=19728] ppid=19711 vsize=130304 CPUtime=1.93
/proc/19728/stat : 19728 (gringo) R 19711 19711 1745 0 -1 4202496 30620 0 0 0 181 12 0 0 20 0 1 0 120184642 133431296 27999 18446744073709551615 4194304 6531320 140734578593312 140734578590296 4543493 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/19728/statm: 32576 27999 283 571 0 31997 0
Current children cumulated CPU time (s) 3.94
Current children cumulated vsize (KiB) 139516

[startup+4.40024 s]
/proc/loadavg: 0.93 0.97 0.98 2/67 19730
/proc/meminfo: memFree=359468/1022884 swapFree=0/0
[pid=19711] ppid=19710 vsize=9212 CPUtime=4.21
/proc/19711/stat : 19711 (aspcud-full) S 19710 19711 1745 0 -1 4202496 800 54109 0 0 0 0 393 28 20 0 1 0 120184437 9433088 364 18446744073709551615 4194304 5129932 140733906466128 140733906464192 139868695782494 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19711/statm: 2303 364 303 229 0 63 0
[pid=19729] ppid=19711 vsize=26088 CPUtime=0.11
/proc/19729/stat : 19729 (clasp) R 19711 19711 1745 0 -1 4202496 6994 0 0 0 8 3 0 0 20 0 1 0 120184863 26714112 6103 18446744073709551615 4194304 6238623 140736207517632 140736207513128 4568360 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19729/statm: 6522 6103 198 500 0 6019 0
[pid=19730] ppid=19711 vsize=22040 CPUtime=0.01
/proc/19730/stat : 19730 (parse.py) S 19711 19711 1745 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 120184863 22568960 1129 18446744073709551615 4194304 6642060 140734174581168 140734174579528 140345248556832 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19730/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 4.33
Current children cumulated vsize (KiB) 57340

[startup+4.60041 s]
/proc/loadavg: 0.93 0.97 0.98 2/67 19730
/proc/meminfo: memFree=359468/1022884 swapFree=0/0
[pid=19711] ppid=19710 vsize=9212 CPUtime=4.21
/proc/19711/stat : 19711 (aspcud-full) S 19710 19711 1745 0 -1 4202496 800 54109 0 0 0 0 393 28 20 0 1 0 120184437 9433088 364 18446744073709551615 4194304 5129932 140733906466128 140733906464192 139868695782494 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19711/statm: 2303 364 303 229 0 63 0
[pid=19729] ppid=19711 vsize=42488 CPUtime=0.3
/proc/19729/stat : 19729 (clasp) R 19711 19711 1745 0 -1 4202496 11494 0 0 0 26 4 0 0 20 0 1 0 120184863 43507712 10157 18446744073709551615 4194304 6238623 140736207517632 140736207515112 4457662 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/19729/statm: 10622 10157 232 500 0 10119 0
[pid=19730] ppid=19711 vsize=22040 CPUtime=0.01
/proc/19730/stat : 19730 (parse.py) S 19711 19711 1745 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 120184863 22568960 1129 18446744073709551615 4194304 6642060 140734174581168 140734174579528 140345248556832 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/19730/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 4.52
Current children cumulated vsize (KiB) 73740

[startup+4.7004 s]
/proc/loadavg: 0.93 0.97 0.98 2/67 19730
/proc/meminfo: memFree=359468/1022884 swapFree=0/0
[pid=19711] ppid=19710 vsize=9212 CPUtime=4.64
/proc/19711/stat : 19711 (aspcud-full) S 19710 19711 1745 0 -1 4202496 836 67141 0 0 0 0 428 36 20 0 1 0 120184437 9433088 364 18446744073709551615 4194304 5129932 140733906466128 140733906463680 139868695782494 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/19711/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 4.64
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 4.7036
CPU time (s): 4.66829
CPU user time (s): 4.29227
CPU system time (s): 0.376023
CPU usage (%): 99.2494
Max. virtual memory (cumulated for all children) (KiB): 144336

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.29227
system time used= 0.376023
maximum resident set size= 116076
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 68213
page faults= 0
swaps= 0
block input operations= 29472
block output operations= 17416
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 75
involuntary context switches= 571

runsolver used 0.016001 second user time and 0.024001 second system time

The end