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/install/rand209.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/install/rand209.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/slowlink/install/rand209.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.91 0.99 0.99 2/64 20674
/proc/meminfo: memFree=451636/1022884 swapFree=0/0
[pid=20674] ppid=20673 vsize=9204 CPUtime=0
/proc/20674/stat : 20674 (aspuncud-full) S 20673 20674 1745 0 -1 4202496 430 0 0 0 0 0 0 0 20 0 1 0 120586662 9424896 331 18446744073709551615 4194304 5129932 140734690229424 140734690226888 140526770435872 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/20674/statm: 2301 331 272 229 0 61 0

[startup+0.13557 s]
/proc/loadavg: 0.91 0.99 0.99 2/64 20674
/proc/meminfo: memFree=451636/1022884 swapFree=0/0
[pid=20674] ppid=20673 vsize=9212 CPUtime=0.03
/proc/20674/stat : 20674 (aspuncud-full) S 20673 20674 1745 0 -1 4202496 695 2812 0 0 0 0 2 1 20 0 1 0 120586662 9433088 364 18446744073709551615 4194304 5129932 140734690229424 140734690228080 140526770291806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20674/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200335 s]
/proc/loadavg: 0.91 0.99 0.99 2/64 20674
/proc/meminfo: memFree=451636/1022884 swapFree=0/0
[pid=20674] ppid=20673 vsize=9212 CPUtime=0.03
/proc/20674/stat : 20674 (aspuncud-full) S 20673 20674 1745 0 -1 4202496 695 2812 0 0 0 0 2 1 20 0 1 0 120586662 9433088 364 18446744073709551615 4194304 5129932 140734690229424 140734690228080 140526770291806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20674/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300323 s]
/proc/loadavg: 0.91 0.99 0.99 2/64 20674
/proc/meminfo: memFree=451636/1022884 swapFree=0/0
[pid=20674] ppid=20673 vsize=9212 CPUtime=0.03
/proc/20674/stat : 20674 (aspuncud-full) S 20673 20674 1745 0 -1 4202496 695 2812 0 0 0 0 2 1 20 0 1 0 120586662 9433088 364 18446744073709551615 4194304 5129932 140734690229424 140734690228080 140526770291806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20674/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700232 s]
/proc/loadavg: 0.91 0.99 0.99 2/64 20674
/proc/meminfo: memFree=451636/1022884 swapFree=0/0
[pid=20674] ppid=20673 vsize=9212 CPUtime=0.03
/proc/20674/stat : 20674 (aspuncud-full) S 20673 20674 1745 0 -1 4202496 695 2812 0 0 0 0 2 1 20 0 1 0 120586662 9433088 364 18446744073709551615 4194304 5129932 140734690229424 140734690228080 140526770291806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20674/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.91 0.99 0.99 2/66 20687
/proc/meminfo: memFree=417016/1022884 swapFree=0/0
[pid=20674] ppid=20673 vsize=9212 CPUtime=0.03
/proc/20674/stat : 20674 (aspuncud-full) S 20673 20674 1745 0 -1 4202496 695 2812 0 0 0 0 2 1 20 0 1 0 120586662 9433088 364 18446744073709551615 4194304 5129932 140734690229424 140734690228080 140526770291806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20674/statm: 2303 364 303 229 0 63 0
[pid=20687] ppid=20674 vsize=55488 CPUtime=1.41
/proc/20687/stat : 20687 (cudf2lp) R 20674 20674 1745 0 -1 4202496 13425 0 0 0 136 5 0 0 20 0 1 0 120586666 56819712 11692 18446744073709551615 4194304 5690517 140735430369728 140735430365896 4963881 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/20687/statm: 13872 11692 160 366 0 13503 0
Current children cumulated CPU time (s) 1.44
Current children cumulated vsize (KiB) 64700

[startup+3.10026 s]
/proc/loadavg: 0.91 0.99 0.99 2/66 20687
/proc/meminfo: memFree=384776/1022884 swapFree=0/0
[pid=20674] ppid=20673 vsize=9212 CPUtime=0.03
/proc/20674/stat : 20674 (aspuncud-full) S 20673 20674 1745 0 -1 4202496 695 2812 0 0 0 0 2 1 20 0 1 0 120586662 9433088 364 18446744073709551615 4194304 5129932 140734690229424 140734690228080 140526770291806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20674/statm: 2303 364 303 229 0 63 0
[pid=20687] ppid=20674 vsize=93028 CPUtime=2.98
/proc/20687/stat : 20687 (cudf2lp) R 20674 20674 1745 0 -1 4202496 26892 0 0 0 288 10 0 0 20 0 1 0 120586666 95260672 20165 18446744073709551615 4194304 5690517 140735430369728 140735430367368 4293647 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/20687/statm: 23257 20165 160 366 0 22888 0
Current children cumulated CPU time (s) 3.01
Current children cumulated vsize (KiB) 102240

[startup+6.30027 s]
/proc/loadavg: 0.91 0.99 0.99 2/66 20688
/proc/meminfo: memFree=346460/1022884 swapFree=0/0
[pid=20674] ppid=20673 vsize=9212 CPUtime=4.15
/proc/20674/stat : 20674 (aspuncud-full) S 20673 20674 1745 0 -1 4202496 723 42133 0 0 0 0 394 21 20 0 1 0 120586662 9433088 364 18446744073709551615 4194304 5129932 140734690229424 140734690228080 140526770291806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20674/statm: 2303 364 303 229 0 63 0
[pid=20688] ppid=20674 vsize=148068 CPUtime=2.02
/proc/20688/stat : 20688 (gringo) R 20674 20674 1745 0 -1 4202496 38271 0 0 0 192 10 0 0 20 0 1 0 120587087 151621632 33089 18446744073709551615 4194304 6531320 140733888706288 140733888702904 4360281 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20688/statm: 37017 33089 282 571 0 36438 0
Current children cumulated CPU time (s) 6.17
Current children cumulated vsize (KiB) 157280

[startup+12.7003 s]
/proc/loadavg: 0.92 0.99 0.99 2/67 20690
/proc/meminfo: memFree=277012/1022884 swapFree=0/0
[pid=20674] ppid=20673 vsize=9212 CPUtime=9.29
/proc/20674/stat : 20674 (aspuncud-full) S 20673 20674 1745 0 -1 4202496 764 153342 0 0 0 0 863 66 20 0 1 0 120586662 9433088 364 18446744073709551615 4194304 5129932 140734690229424 140734690227488 140526770291806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20674/statm: 2303 364 303 229 0 63 0
[pid=20689] ppid=20674 vsize=139532 CPUtime=3.19
/proc/20689/stat : 20689 (unclasp) R 20674 20674 1745 0 -1 4202496 40549 0 0 0 307 12 0 0 20 0 1 0 120587608 142880768 34371 18446744073709551615 4194304 6012874 140733217636352 140733217635672 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20689/statm: 34883 34371 226 444 0 34431 0
[pid=20690] ppid=20674 vsize=22044 CPUtime=0
/proc/20690/stat : 20690 (parse.py) S 20674 20674 1745 0 -1 4202496 1323 0 0 0 0 0 0 0 20 0 1 0 120587608 22573056 1132 18446744073709551615 4194304 6642060 140734083058432 140734083056632 139749425272608 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20690/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 12.48
Current children cumulated vsize (KiB) 170788

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

[startup+12.8004 s]
/proc/loadavg: 0.92 0.99 0.99 2/67 20690
/proc/meminfo: memFree=277012/1022884 swapFree=0/0
[pid=20674] ppid=20673 vsize=9212 CPUtime=9.29
/proc/20674/stat : 20674 (aspuncud-full) S 20673 20674 1745 0 -1 4202496 764 153342 0 0 0 0 863 66 20 0 1 0 120586662 9433088 364 18446744073709551615 4194304 5129932 140734690229424 140734690227488 140526770291806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20674/statm: 2303 364 303 229 0 63 0
[pid=20689] ppid=20674 vsize=139532 CPUtime=3.3
/proc/20689/stat : 20689 (unclasp) R 20674 20674 1745 0 -1 4202496 40549 0 0 0 317 13 0 0 20 0 1 0 120587608 142880768 34371 18446744073709551615 4194304 6012874 140733217636352 140733217635672 4548456 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20689/statm: 34883 34371 226 444 0 34431 0
[pid=20690] ppid=20674 vsize=22044 CPUtime=0
/proc/20690/stat : 20690 (parse.py) S 20674 20674 1745 0 -1 4202496 1323 0 0 0 0 0 0 0 20 0 1 0 120587608 22573056 1132 18446744073709551615 4194304 6642060 140734083058432 140734083056632 139749425272608 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20690/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 12.59
Current children cumulated vsize (KiB) 170788

[startup+16.0003 s]
/proc/loadavg: 0.93 0.99 0.99 2/67 20690
/proc/meminfo: memFree=277012/1022884 swapFree=0/0
[pid=20674] ppid=20673 vsize=9212 CPUtime=9.29
/proc/20674/stat : 20674 (aspuncud-full) S 20673 20674 1745 0 -1 4202496 764 153342 0 0 0 0 863 66 20 0 1 0 120586662 9433088 364 18446744073709551615 4194304 5129932 140734690229424 140734690227488 140526770291806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20674/statm: 2303 364 303 229 0 63 0
[pid=20689] ppid=20674 vsize=139532 CPUtime=6.47
/proc/20689/stat : 20689 (unclasp) R 20674 20674 1745 0 -1 4202496 40549 0 0 0 634 13 0 0 20 0 1 0 120587608 142880768 34371 18446744073709551615 4194304 6012874 140733217636352 140733217635672 4506598 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20689/statm: 34883 34371 226 444 0 34431 0
[pid=20690] ppid=20674 vsize=22044 CPUtime=0
/proc/20690/stat : 20690 (parse.py) S 20674 20674 1745 0 -1 4202496 1323 0 0 0 0 0 0 0 20 0 1 0 120587608 22573056 1132 18446744073709551615 4194304 6642060 140734083058432 140734083056632 139749425272608 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20690/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 15.76
Current children cumulated vsize (KiB) 170788

[startup+16.8003 s]
/proc/loadavg: 0.93 0.99 0.99 2/67 20690
/proc/meminfo: memFree=277012/1022884 swapFree=0/0
[pid=20674] ppid=20673 vsize=9212 CPUtime=9.29
/proc/20674/stat : 20674 (aspuncud-full) S 20673 20674 1745 0 -1 4202496 764 153342 0 0 0 0 863 66 20 0 1 0 120586662 9433088 364 18446744073709551615 4194304 5129932 140734690229424 140734690227488 140526770291806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20674/statm: 2303 364 303 229 0 63 0
[pid=20689] ppid=20674 vsize=139532 CPUtime=7.27
/proc/20689/stat : 20689 (unclasp) R 20674 20674 1745 0 -1 4202496 40549 0 0 0 713 14 0 0 20 0 1 0 120587608 142880768 34371 18446744073709551615 4194304 6012874 140733217636352 140733217635672 4548507 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20689/statm: 34883 34371 226 444 0 34431 0
[pid=20690] ppid=20674 vsize=22044 CPUtime=0
/proc/20690/stat : 20690 (parse.py) S 20674 20674 1745 0 -1 4202496 1323 0 0 0 0 0 0 0 20 0 1 0 120587608 22573056 1132 18446744073709551615 4194304 6642060 140734083058432 140734083056632 139749425272608 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20690/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 16.56
Current children cumulated vsize (KiB) 170788

[startup+17.6004 s]
/proc/loadavg: 0.93 0.99 0.99 2/67 20690
/proc/meminfo: memFree=277012/1022884 swapFree=0/0
[pid=20674] ppid=20673 vsize=9212 CPUtime=9.29
/proc/20674/stat : 20674 (aspuncud-full) S 20673 20674 1745 0 -1 4202496 764 153342 0 0 0 0 863 66 20 0 1 0 120586662 9433088 364 18446744073709551615 4194304 5129932 140734690229424 140734690227488 140526770291806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20674/statm: 2303 364 303 229 0 63 0
[pid=20689] ppid=20674 vsize=139532 CPUtime=8.06
/proc/20689/stat : 20689 (unclasp) R 20674 20674 1745 0 -1 4202496 40549 0 0 0 792 14 0 0 20 0 1 0 120587608 142880768 34371 18446744073709551615 4194304 6012874 140733217636352 140733217635672 4548180 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20689/statm: 34883 34371 226 444 0 34431 0
[pid=20690] ppid=20674 vsize=22044 CPUtime=0
/proc/20690/stat : 20690 (parse.py) S 20674 20674 1745 0 -1 4202496 1323 0 0 0 0 0 0 0 20 0 1 0 120587608 22573056 1132 18446744073709551615 4194304 6642060 140734083058432 140734083056632 139749425272608 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20690/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 17.35
Current children cumulated vsize (KiB) 170788

[startup+18.0003 s]
/proc/loadavg: 0.93 0.99 0.99 2/67 20690
/proc/meminfo: memFree=277012/1022884 swapFree=0/0
[pid=20674] ppid=20673 vsize=9212 CPUtime=9.29
/proc/20674/stat : 20674 (aspuncud-full) S 20673 20674 1745 0 -1 4202496 764 153342 0 0 0 0 863 66 20 0 1 0 120586662 9433088 364 18446744073709551615 4194304 5129932 140734690229424 140734690227488 140526770291806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20674/statm: 2303 364 303 229 0 63 0
[pid=20689] ppid=20674 vsize=139532 CPUtime=8.46
/proc/20689/stat : 20689 (unclasp) R 20674 20674 1745 0 -1 4202496 40549 0 0 0 832 14 0 0 20 0 1 0 120587608 142880768 34371 18446744073709551615 4194304 6012874 140733217636352 140733217635416 5256225 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/20689/statm: 34883 34371 226 444 0 34431 0
[pid=20690] ppid=20674 vsize=22192 CPUtime=0
/proc/20690/stat : 20690 (parse.py) S 20674 20674 1745 0 -1 4202496 1332 0 0 0 0 0 0 0 20 0 1 0 120587608 22724608 1141 18446744073709551615 4194304 6642060 140734083058432 140734083056712 139749425272608 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/20690/statm: 5548 1141 508 598 0 634 0
Current children cumulated CPU time (s) 17.75
Current children cumulated vsize (KiB) 170936

[startup+18.1003 s]
/proc/loadavg: 0.93 0.99 0.99 2/67 20690
/proc/meminfo: memFree=277012/1022884 swapFree=0/0
[pid=20674] ppid=20673 vsize=9212 CPUtime=17.86
/proc/20674/stat : 20674 (aspuncud-full) S 20673 20674 1745 0 -1 4202496 797 195255 0 0 0 0 1702 84 20 0 1 0 120586662 9433088 364 18446744073709551615 4194304 5129932 140734690229424 140734690226976 140526770291806 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/20674/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 17.86
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 18.1038
CPU time (s): 17.8851
CPU user time (s): 17.0291
CPU system time (s): 0.856053
CPU usage (%): 98.7923
Max. virtual memory (cumulated for all children) (KiB): 477504

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 17.0291
system time used= 0.856053
maximum resident set size= 407704
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 196287
page faults= 0
swaps= 0
block input operations= 68440
block output operations= 51344
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 107
involuntary context switches= 2119

runsolver used 0.048003 second user time and 0.060003 second system time

The end