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/upgrade/difficult/rand981.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/upgrade/difficult/rand981.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/slowlink/upgrade/difficult/rand981.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.97 0.97 0.97 2/59 5697
/proc/meminfo: memFree=327524/1022884 swapFree=0/0
[pid=5697] ppid=5696 vsize=9204 CPUtime=0
/proc/5697/stat : 5697 (aspuncud-full) S 5696 5697 1733 0 -1 4202496 431 0 0 0 0 0 0 0 20 0 1 0 120644657 9424896 331 18446744073709551615 4194304 5129932 140734250316704 140734250314168 140064176383776 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/5697/statm: 2301 331 272 229 0 61 0

[startup+0.207111 s]
/proc/loadavg: 0.97 0.97 0.97 2/59 5697
/proc/meminfo: memFree=327524/1022884 swapFree=0/0
[pid=5697] ppid=5696 vsize=9212 CPUtime=0.03
/proc/5697/stat : 5697 (aspuncud-full) S 5696 5697 1733 0 -1 4202496 702 2810 0 0 0 0 2 1 20 0 1 0 120644657 9433088 364 18446744073709551615 4194304 5129932 140734250316704 140734250315360 140064176239710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5697/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300278 s]
/proc/loadavg: 0.97 0.97 0.97 2/59 5697
/proc/meminfo: memFree=327524/1022884 swapFree=0/0
[pid=5697] ppid=5696 vsize=9212 CPUtime=0.03
/proc/5697/stat : 5697 (aspuncud-full) S 5696 5697 1733 0 -1 4202496 702 2810 0 0 0 0 2 1 20 0 1 0 120644657 9433088 364 18446744073709551615 4194304 5129932 140734250316704 140734250315360 140064176239710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5697/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.400266 s]
/proc/loadavg: 0.97 0.97 0.97 2/59 5697
/proc/meminfo: memFree=327524/1022884 swapFree=0/0
[pid=5697] ppid=5696 vsize=9212 CPUtime=0.03
/proc/5697/stat : 5697 (aspuncud-full) S 5696 5697 1733 0 -1 4202496 702 2810 0 0 0 0 2 1 20 0 1 0 120644657 9433088 364 18446744073709551615 4194304 5129932 140734250316704 140734250315360 140064176239710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5697/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700205 s]
/proc/loadavg: 0.97 0.97 0.97 2/59 5697
/proc/meminfo: memFree=327524/1022884 swapFree=0/0
[pid=5697] ppid=5696 vsize=9212 CPUtime=0.03
/proc/5697/stat : 5697 (aspuncud-full) S 5696 5697 1733 0 -1 4202496 702 2810 0 0 0 0 2 1 20 0 1 0 120644657 9433088 364 18446744073709551615 4194304 5129932 140734250316704 140734250315360 140064176239710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5697/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50027 s]
/proc/loadavg: 0.97 0.97 0.97 2/61 5710
/proc/meminfo: memFree=270576/1022884 swapFree=0/0
[pid=5697] ppid=5696 vsize=9212 CPUtime=0.03
/proc/5697/stat : 5697 (aspuncud-full) S 5696 5697 1733 0 -1 4202496 702 2810 0 0 0 0 2 1 20 0 1 0 120644657 9433088 364 18446744073709551615 4194304 5129932 140734250316704 140734250315360 140064176239710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5697/statm: 2303 364 303 229 0 63 0
[pid=5710] ppid=5697 vsize=50676 CPUtime=1.35
/proc/5710/stat : 5710 (cudf2lp) R 5697 5697 1733 0 -1 4202496 14749 0 0 0 130 5 0 0 20 0 1 0 120644660 51892224 11350 18446744073709551615 4194304 5690517 140735364225600 140735364223240 4293666 0 0 16781316 0 0 0 0 17 0 0 0 10 0 0
/proc/5710/statm: 12669 11350 160 366 0 12300 0
Current children cumulated CPU time (s) 1.38
Current children cumulated vsize (KiB) 59888

[startup+3.1003 s]
/proc/loadavg: 0.97 0.97 0.97 2/61 5710
/proc/meminfo: memFree=247604/1022884 swapFree=0/0
[pid=5697] ppid=5696 vsize=9212 CPUtime=0.03
/proc/5697/stat : 5697 (aspuncud-full) S 5696 5697 1733 0 -1 4202496 702 2810 0 0 0 0 2 1 20 0 1 0 120644657 9433088 364 18446744073709551615 4194304 5129932 140734250316704 140734250315360 140064176239710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5697/statm: 2303 364 303 229 0 63 0
[pid=5710] ppid=5697 vsize=93028 CPUtime=2.92
/proc/5710/stat : 5710 (cudf2lp) R 5697 5697 1733 0 -1 4202496 27103 0 0 0 279 13 0 0 20 0 1 0 120644660 95260672 20375 18446744073709551615 4194304 5690517 140735364225600 140735364223240 4292737 0 0 16781316 0 0 0 0 17 0 0 0 12 0 0
/proc/5710/statm: 23257 20375 160 366 0 22888 0
Current children cumulated CPU time (s) 2.95
Current children cumulated vsize (KiB) 102240

[startup+6.30029 s]
/proc/loadavg: 0.97 0.97 0.97 2/61 5711
/proc/meminfo: memFree=255872/1022884 swapFree=0/0
[pid=5697] ppid=5696 vsize=9212 CPUtime=4.39
/proc/5697/stat : 5697 (aspuncud-full) S 5696 5697 1733 0 -1 4202496 730 42133 0 0 0 0 413 26 20 0 1 0 120644657 9433088 364 18446744073709551615 4194304 5129932 140734250316704 140734250315360 140064176239710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5697/statm: 2303 364 303 229 0 63 0
[pid=5711] ppid=5697 vsize=48944 CPUtime=1.73
/proc/5711/stat : 5711 (gringo) R 5697 5697 1733 0 -1 4202496 13672 0 0 0 161 12 0 0 20 0 1 0 120645112 50118656 10539 18446744073709551615 4194304 6531320 140736957630768 140736957627384 5520829 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/5711/statm: 12236 10539 259 571 0 11657 0
Current children cumulated CPU time (s) 6.12
Current children cumulated vsize (KiB) 58156

[startup+12.7004 s]
/proc/loadavg: 0.98 0.97 0.97 2/62 5713
/proc/meminfo: memFree=289804/1022884 swapFree=0/0
[pid=5697] ppid=5696 vsize=9212 CPUtime=11.17
/proc/5697/stat : 5697 (aspuncud-full) S 5696 5697 1733 0 -1 4202496 769 152415 0 0 0 0 1026 91 20 0 1 0 120644657 9433088 364 18446744073709551615 4194304 5129932 140734250316704 140734250314768 140064176239710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5697/statm: 2303 364 303 229 0 63 0
[pid=5712] ppid=5697 vsize=146696 CPUtime=1.12
/proc/5712/stat : 5712 (unclasp) R 5697 5697 1733 0 -1 4202496 40258 0 1 0 98 14 0 0 20 0 1 0 120645808 150216704 36076 18446744073709551615 4194304 6012874 140737263130128 140737263128888 4285392 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/5712/statm: 36674 36076 201 444 0 36222 0
[pid=5713] ppid=5697 vsize=22040 CPUtime=0.02
/proc/5713/stat : 5713 (parse.py) S 5697 5697 1733 0 -1 4202496 1306 0 13 0 0 2 0 0 20 0 1 0 120645808 22568960 1128 18446744073709551615 4194304 6642060 140734364433040 140734364431400 139901413107488 0 0 16777220 20994 0 0 0 17 0 0 0 25 0 0
/proc/5713/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.31
Current children cumulated vsize (KiB) 177948

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

[startup+12.9004 s]
/proc/loadavg: 0.98 0.97 0.97 2/62 5713
/proc/meminfo: memFree=289804/1022884 swapFree=0/0
[pid=5697] ppid=5696 vsize=9212 CPUtime=11.17
/proc/5697/stat : 5697 (aspuncud-full) S 5696 5697 1733 0 -1 4202496 769 152415 0 0 0 0 1026 91 20 0 1 0 120644657 9433088 364 18446744073709551615 4194304 5129932 140734250316704 140734250314768 140064176239710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5697/statm: 2303 364 303 229 0 63 0
[pid=5712] ppid=5697 vsize=138880 CPUtime=1.33
/proc/5712/stat : 5712 (unclasp) R 5697 5697 1733 0 -1 4202496 40357 0 1 0 118 15 0 0 20 0 1 0 120645808 142213120 34190 18446744073709551615 4194304 6012874 140737263130128 140737263129304 5251088 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/5712/statm: 34720 34190 218 444 0 34268 0
[pid=5713] ppid=5697 vsize=22040 CPUtime=0.02
/proc/5713/stat : 5713 (parse.py) S 5697 5697 1733 0 -1 4202496 1306 0 13 0 0 2 0 0 20 0 1 0 120645808 22568960 1128 18446744073709551615 4194304 6642060 140734364433040 140734364431400 139901413107488 0 0 16777220 20994 0 0 0 17 0 0 0 25 0 0
/proc/5713/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.52
Current children cumulated vsize (KiB) 170132

[startup+13.7004 s]
/proc/loadavg: 0.98 0.97 0.97 2/62 5713
/proc/meminfo: memFree=274560/1022884 swapFree=0/0
[pid=5697] ppid=5696 vsize=9212 CPUtime=11.17
/proc/5697/stat : 5697 (aspuncud-full) S 5696 5697 1733 0 -1 4202496 769 152415 0 0 0 0 1026 91 20 0 1 0 120644657 9433088 364 18446744073709551615 4194304 5129932 140734250316704 140734250314768 140064176239710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5697/statm: 2303 364 303 229 0 63 0
[pid=5712] ppid=5697 vsize=138880 CPUtime=2.12
/proc/5712/stat : 5712 (unclasp) R 5697 5697 1733 0 -1 4202496 40366 0 1 0 197 15 0 0 20 0 1 0 120645808 142213120 34199 18446744073709551615 4194304 6012874 140737263130128 140737263129448 4548944 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/5712/statm: 34720 34199 226 444 0 34268 0
[pid=5713] ppid=5697 vsize=22044 CPUtime=0.02
/proc/5713/stat : 5713 (parse.py) S 5697 5697 1733 0 -1 4202496 1310 0 13 0 0 2 0 0 20 0 1 0 120645808 22573056 1132 18446744073709551615 4194304 6642060 140734364433040 140734364431240 139901413107488 0 0 16777220 20994 0 0 0 17 0 0 0 25 0 0
/proc/5713/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 13.31
Current children cumulated vsize (KiB) 170136

[startup+14.1004 s]
/proc/loadavg: 0.98 0.97 0.97 2/62 5713
/proc/meminfo: memFree=274560/1022884 swapFree=0/0
[pid=5697] ppid=5696 vsize=9212 CPUtime=11.17
/proc/5697/stat : 5697 (aspuncud-full) S 5696 5697 1733 0 -1 4202496 769 152415 0 0 0 0 1026 91 20 0 1 0 120644657 9433088 364 18446744073709551615 4194304 5129932 140734250316704 140734250314768 140064176239710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5697/statm: 2303 364 303 229 0 63 0
[pid=5712] ppid=5697 vsize=138880 CPUtime=2.52
/proc/5712/stat : 5712 (unclasp) R 5697 5697 1733 0 -1 4202496 40366 0 1 0 237 15 0 0 20 0 1 0 120645808 142213120 34199 18446744073709551615 4194304 6012874 140737263130128 140737263129448 4548180 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/5712/statm: 34720 34199 226 444 0 34268 0
[pid=5713] ppid=5697 vsize=22044 CPUtime=0.02
/proc/5713/stat : 5713 (parse.py) S 5697 5697 1733 0 -1 4202496 1310 0 13 0 0 2 0 0 20 0 1 0 120645808 22573056 1132 18446744073709551615 4194304 6642060 140734364433040 140734364431240 139901413107488 0 0 16777220 20994 0 0 0 17 0 0 0 25 0 0
/proc/5713/statm: 5511 1132 508 598 0 597 0
Current children cumulated CPU time (s) 13.71
Current children cumulated vsize (KiB) 170136

[startup+14.3005 s]
/proc/loadavg: 0.98 0.97 0.97 2/62 5713
/proc/meminfo: memFree=274560/1022884 swapFree=0/0
[pid=5697] ppid=5696 vsize=9212 CPUtime=13.9
/proc/5697/stat : 5697 (aspuncud-full) S 5696 5697 1733 0 -1 4202496 804 194135 0 14 0 0 1277 113 20 0 1 0 120644657 9433088 364 18446744073709551615 4194304 5129932 140734250316704 140734250314256 140064176239710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5697/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 13.9
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 14.3176
CPU time (s): 13.9369
CPU user time (s): 12.7808
CPU system time (s): 1.15607
CPU usage (%): 97.3407
Max. virtual memory (cumulated for all children) (KiB): 474280

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 12.7808
system time used= 1.15607
maximum resident set size= 403996
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 195171
page faults= 15
swaps= 0
block input operations= 70080
block output operations= 51144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 162
involuntary context switches= 1776

runsolver used 0.040002 second user time and 0.056003 second system time

The end