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/upgrade/install/rand937.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand937.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/upgrade/install/rand937.cudf.result -count(down),-notuptodate(solution),-aligned(solution,source,sourceversion),-unsat_recommends(solution),-count(new) 

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.66 0.18 0.06 3/65 13526
/proc/meminfo: memFree=526172/1022884 swapFree=0/0
[pid=13526] ppid=13525 vsize=9204 CPUtime=0
/proc/13526/stat : 13526 (aspcud-full) S 13525 13526 32685 0 -1 4202496 431 0 0 0 0 0 0 0 20 0 1 0 38817918 9424896 332 18446744073709551615 4194304 5129932 140734158563168 140734158560632 140164650751776 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/13526/statm: 2301 332 272 229 0 61 0

[startup+0.128649 s]
/proc/loadavg: 0.66 0.18 0.06 3/65 13526
/proc/meminfo: memFree=526172/1022884 swapFree=0/0
[pid=13526] ppid=13525 vsize=9212 CPUtime=0.05
/proc/13526/stat : 13526 (aspcud-full) S 13525 13526 32685 0 -1 4202496 741 3617 0 0 0 0 4 1 20 0 1 0 38817918 9433088 365 18446744073709551615 4194304 5129932 140734158563168 140734158561824 140164650607710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13526/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200322 s]
/proc/loadavg: 0.66 0.18 0.06 3/65 13526
/proc/meminfo: memFree=526172/1022884 swapFree=0/0
[pid=13526] ppid=13525 vsize=9212 CPUtime=0.05
/proc/13526/stat : 13526 (aspcud-full) S 13525 13526 32685 0 -1 4202496 741 3617 0 0 0 0 4 1 20 0 1 0 38817918 9433088 365 18446744073709551615 4194304 5129932 140734158563168 140734158561824 140164650607710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13526/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300299 s]
/proc/loadavg: 0.66 0.18 0.06 3/65 13526
/proc/meminfo: memFree=526172/1022884 swapFree=0/0
[pid=13526] ppid=13525 vsize=9212 CPUtime=0.05
/proc/13526/stat : 13526 (aspcud-full) S 13525 13526 32685 0 -1 4202496 741 3617 0 0 0 0 4 1 20 0 1 0 38817918 9433088 365 18446744073709551615 4194304 5129932 140734158563168 140734158561824 140164650607710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13526/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700227 s]
/proc/loadavg: 0.66 0.18 0.06 3/65 13526
/proc/meminfo: memFree=526172/1022884 swapFree=0/0
[pid=13526] ppid=13525 vsize=9212 CPUtime=0.05
/proc/13526/stat : 13526 (aspcud-full) S 13525 13526 32685 0 -1 4202496 741 3617 0 0 0 0 4 1 20 0 1 0 38817918 9433088 365 18446744073709551615 4194304 5129932 140734158563168 140734158561824 140164650607710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13526/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 0.66 0.18 0.06 3/67 13542
/proc/meminfo: memFree=506308/1022884 swapFree=0/0
[pid=13526] ppid=13525 vsize=9212 CPUtime=0.05
/proc/13526/stat : 13526 (aspcud-full) S 13525 13526 32685 0 -1 4202496 741 3617 0 0 0 0 4 1 20 0 1 0 38817918 9433088 365 18446744073709551615 4194304 5129932 140734158563168 140734158561824 140164650607710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13526/statm: 2303 365 303 229 0 63 0
[pid=13542] ppid=13526 vsize=18684 CPUtime=0.68
/proc/13542/stat : 13542 (cudf2lp) R 13526 13526 32685 0 -1 4202496 5261 0 0 0 66 2 0 0 20 0 1 0 38817926 19132416 4360 18446744073709551615 4194304 5690517 140737251005824 140737251003464 4348960 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/13542/statm: 4671 4360 159 366 0 4302 0
Current children cumulated CPU time (s) 0.73
Current children cumulated vsize (KiB) 27896

[startup+3.1003 s]
/proc/loadavg: 0.85 0.23 0.08 3/67 13542
/proc/meminfo: memFree=490188/1022884 swapFree=0/0
[pid=13526] ppid=13525 vsize=9212 CPUtime=0.05
/proc/13526/stat : 13526 (aspcud-full) S 13525 13526 32685 0 -1 4202496 741 3617 0 0 0 0 4 1 20 0 1 0 38817918 9433088 365 18446744073709551615 4194304 5129932 140734158563168 140734158561824 140164650607710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13526/statm: 2303 365 303 229 0 63 0
[pid=13542] ppid=13526 vsize=56856 CPUtime=1.48
/proc/13542/stat : 13542 (cudf2lp) R 13526 13526 32685 0 -1 4202496 13565 0 0 0 142 6 0 0 20 0 1 0 38817926 58220544 11831 18446744073709551615 4194304 5690517 140737251005824 140737251002024 4970688 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/13542/statm: 14214 11831 160 366 0 13845 0
Current children cumulated CPU time (s) 1.53
Current children cumulated vsize (KiB) 66068
heavy processes:
  %CPU=46 pid=13513 uid=0 cmd=/usr/bin/apt-get -o quiet=1 update -o quiet=2 

[startup+6.30031 s]
/proc/loadavg: 0.85 0.23 0.08 3/64 13543
/proc/meminfo: memFree=448556/1022884 swapFree=0/0
[pid=13526] ppid=13525 vsize=9212 CPUtime=0.05
/proc/13526/stat : 13526 (aspcud-full) S 13525 13526 32685 0 -1 4202496 741 3617 0 0 0 0 4 1 20 0 1 0 38817918 9433088 365 18446744073709551615 4194304 5129932 140734158563168 140734158561824 140164650607710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13526/statm: 2303 365 303 229 0 63 0
[pid=13542] ppid=13526 vsize=99148 CPUtime=3.07
/proc/13542/stat : 13542 (cudf2lp) R 13526 13526 32685 0 -1 4202496 27947 0 0 0 293 14 0 0 20 0 1 0 38817926 101527552 21219 18446744073709551615 4194304 5690517 140737251005824 140737251003464 4357501 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/13542/statm: 24787 21219 160 366 0 24418 0
Current children cumulated CPU time (s) 3.12
Current children cumulated vsize (KiB) 108360
heavy processes:
  %CPU=48 pid=13513 uid=0 cmd=/usr/bin/apt-get -o quiet=1 update -o quiet=2 

[startup+12.7003 s]
/proc/loadavg: 0.94 0.27 0.09 2/59 13627
/proc/meminfo: memFree=323108/1022884 swapFree=0/0
[pid=13526] ppid=13525 vsize=9212 CPUtime=5.14
/proc/13526/stat : 13526 (aspcud-full) S 13525 13526 32685 0 -1 4202496 767 44896 0 0 0 0 484 30 20 0 1 0 38817918 9433088 365 18446744073709551615 4194304 5129932 140734158563168 140734158561824 140164650607710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13526/statm: 2303 365 303 229 0 63 0
[pid=13627] ppid=13526 vsize=208868 CPUtime=2.9
/proc/13627/stat : 13627 (gringo) R 13526 13526 32685 0 -1 4202496 53488 0 0 0 271 19 0 0 20 0 1 0 38818896 213880832 43183 18446744073709551615 4194304 6531320 140735927803328 140735927799944 4593310 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13627/statm: 52217 43183 280 571 0 51638 0
Current children cumulated CPU time (s) 8.04
Current children cumulated vsize (KiB) 218080
heavy processes:

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

[startup+12.8033 s]
/proc/loadavg: 0.94 0.27 0.09 2/59 13627
/proc/meminfo: memFree=271524/1022884 swapFree=0/0
[pid=13526] ppid=13525 vsize=9212 CPUtime=5.14
/proc/13526/stat : 13526 (aspcud-full) S 13525 13526 32685 0 -1 4202496 767 44896 0 0 0 0 484 30 20 0 1 0 38817918 9433088 365 18446744073709551615 4194304 5129932 140734158563168 140734158561824 140164650607710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13526/statm: 2303 365 303 229 0 63 0
[pid=13627] ppid=13526 vsize=212964 CPUtime=2.99
/proc/13627/stat : 13627 (gringo) R 13526 13526 32685 0 -1 4202496 54891 0 0 0 280 19 0 0 20 0 1 0 38818896 218075136 44586 18446744073709551615 4194304 6531320 140735927803328 140735927799944 4358998 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13627/statm: 53241 44586 280 571 0 52662 0
Current children cumulated CPU time (s) 8.13
Current children cumulated vsize (KiB) 222176

[startup+16.0003 s]
/proc/loadavg: 0.94 0.27 0.09 2/59 13627
/proc/meminfo: memFree=51548/1022884 swapFree=0/0
[pid=13526] ppid=13525 vsize=9212 CPUtime=5.14
/proc/13526/stat : 13526 (aspcud-full) S 13525 13526 32685 0 -1 4202496 767 44896 0 0 0 0 484 30 20 0 1 0 38817918 9433088 365 18446744073709551615 4194304 5129932 140734158563168 140734158561824 140164650607710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13526/statm: 2303 365 303 229 0 63 0
[pid=13627] ppid=13526 vsize=543740 CPUtime=6.15
/proc/13627/stat : 13627 (gringo) R 13526 13526 32685 0 -1 4202496 128170 0 0 0 574 41 0 0 20 0 1 0 38818896 556789760 109672 18446744073709551615 4194304 6531320 140735927803328 140735927799608 4596844 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13627/statm: 135935 109672 282 571 0 135356 0
Current children cumulated CPU time (s) 11.29
Current children cumulated vsize (KiB) 552952

[startup+17.6002 s]
/proc/loadavg: 0.95 0.28 0.10 2/60 13629
/proc/meminfo: memFree=321992/1022884 swapFree=0/0
[pid=13526] ppid=13525 vsize=9212 CPUtime=12.25
/proc/13526/stat : 13526 (aspcud-full) S 13525 13526 32685 0 -1 4202496 808 182046 0 0 0 0 1139 86 20 0 1 0 38817918 9433088 365 18446744073709551615 4194304 5129932 140734158563168 140734158561232 140164650607710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13526/statm: 2303 365 303 229 0 63 0
[pid=13628] ppid=13526 vsize=166508 CPUtime=0.56
/proc/13628/stat : 13628 (clasp) R 13526 13526 32685 0 -1 4202496 46195 0 0 0 43 13 0 0 20 0 1 0 38819620 170504192 39958 18446744073709551615 4194304 6238623 140737326636160 140737326633720 4518824 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/13628/statm: 41627 39958 209 500 0 41124 0
[pid=13629] ppid=13526 vsize=22040 CPUtime=0
/proc/13629/stat : 13629 (parse.py) S 13526 13526 32685 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 38819620 22568960 1128 18446744073709551615 4194304 6642060 140735586676656 140735586675016 139752033470240 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/13629/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.81
Current children cumulated vsize (KiB) 197760

[startup+18.4003 s]
/proc/loadavg: 0.95 0.28 0.10 2/60 13629
/proc/meminfo: memFree=321992/1022884 swapFree=0/0
[pid=13526] ppid=13525 vsize=9212 CPUtime=12.25
/proc/13526/stat : 13526 (aspcud-full) S 13525 13526 32685 0 -1 4202496 808 182046 0 0 0 0 1139 86 20 0 1 0 38817918 9433088 365 18446744073709551615 4194304 5129932 140734158563168 140734158561232 140164650607710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13526/statm: 2303 365 303 229 0 63 0
[pid=13628] ppid=13526 vsize=164300 CPUtime=1.35
/proc/13628/stat : 13628 (clasp) R 13526 13526 32685 0 -1 4202496 48738 0 0 0 122 13 0 0 20 0 1 0 38819620 168243200 40200 18446744073709551615 4194304 6238623 140737326636160 140737326633856 4667161 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/13628/statm: 41075 40200 263 500 0 40572 0
[pid=13629] ppid=13526 vsize=22040 CPUtime=0
/proc/13629/stat : 13629 (parse.py) S 13526 13526 32685 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 38819620 22568960 1128 18446744073709551615 4194304 6642060 140735586676656 140735586675016 139752033470240 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/13629/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 13.6
Current children cumulated vsize (KiB) 195552

[startup+18.8032 s]
/proc/loadavg: 0.95 0.28 0.10 2/60 13629
/proc/meminfo: memFree=320752/1022884 swapFree=0/0
[pid=13526] ppid=13525 vsize=9212 CPUtime=12.25
/proc/13526/stat : 13526 (aspcud-full) S 13525 13526 32685 0 -1 4202496 808 182046 0 0 0 0 1139 86 20 0 1 0 38817918 9433088 365 18446744073709551615 4194304 5129932 140734158563168 140734158561232 140164650607710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13526/statm: 2303 365 303 229 0 63 0
[pid=13628] ppid=13526 vsize=164300 CPUtime=1.75
/proc/13628/stat : 13628 (clasp) R 13526 13526 32685 0 -1 4202496 48739 0 0 0 162 13 0 0 20 0 1 0 38819620 168243200 40201 18446744073709551615 4194304 6238623 140737326636160 140737326633184 4586401 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/13628/statm: 41075 40201 264 500 0 40572 0
[pid=13629] ppid=13526 vsize=22040 CPUtime=0
/proc/13629/stat : 13629 (parse.py) S 13526 13526 32685 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 38819620 22568960 1128 18446744073709551615 4194304 6642060 140735586676656 140735586675016 139752033470240 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/13629/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 14
Current children cumulated vsize (KiB) 195552

[startup+19.2003 s]
/proc/loadavg: 0.95 0.28 0.10 2/60 13629
/proc/meminfo: memFree=320752/1022884 swapFree=0/0
[pid=13526] ppid=13525 vsize=9212 CPUtime=12.25
/proc/13526/stat : 13526 (aspcud-full) S 13525 13526 32685 0 -1 4202496 808 182046 0 0 0 0 1139 86 20 0 1 0 38817918 9433088 365 18446744073709551615 4194304 5129932 140734158563168 140734158561232 140164650607710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13526/statm: 2303 365 303 229 0 63 0
[pid=13628] ppid=13526 vsize=164300 CPUtime=2.15
/proc/13628/stat : 13628 (clasp) R 13526 13526 32685 0 -1 4202496 48739 0 0 0 202 13 0 0 20 0 1 0 38819620 168243200 40201 18446744073709551615 4194304 6238623 140737326636160 140737326633184 4635539 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/13628/statm: 41075 40201 264 500 0 40572 0
[pid=13629] ppid=13526 vsize=22040 CPUtime=0
/proc/13629/stat : 13629 (parse.py) S 13526 13526 32685 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 38819620 22568960 1128 18446744073709551615 4194304 6642060 140735586676656 140735586675016 139752033470240 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/13629/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 14.4
Current children cumulated vsize (KiB) 195552

[startup+19.3003 s]
/proc/loadavg: 0.95 0.28 0.10 2/60 13629
/proc/meminfo: memFree=320752/1022884 swapFree=0/0
[pid=13526] ppid=13525 vsize=9212 CPUtime=12.25
/proc/13526/stat : 13526 (aspcud-full) S 13525 13526 32685 0 -1 4202496 808 182046 0 0 0 0 1139 86 20 0 1 0 38817918 9433088 365 18446744073709551615 4194304 5129932 140734158563168 140734158561232 140164650607710 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13526/statm: 2303 365 303 229 0 63 0
[pid=13628] ppid=13526 vsize=164300 CPUtime=2.25
/proc/13628/stat : 13628 (clasp) R 13526 13526 32685 0 -1 4202496 48739 0 0 0 212 13 0 0 20 0 1 0 38819620 168243200 40201 18446744073709551615 4194304 6238623 140737326636160 140737326633184 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/13628/statm: 41075 40201 264 500 0 40572 0
[pid=13629] ppid=13526 vsize=22040 CPUtime=0
/proc/13629/stat : 13629 (parse.py) S 13526 13526 32685 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 38819620 22568960 1128 18446744073709551615 4194304 6642060 140735586676656 140735586675016 139752033470240 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/13629/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 14.5
Current children cumulated vsize (KiB) 195552

Child status: 0
Real time (s): 19.3913
CPU time (s): 14.6329
CPU user time (s): 13.5648
CPU system time (s): 1.06807
CPU usage (%): 75.4613
Max. virtual memory (cumulated for all children) (KiB): 592776

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.5648
system time used= 1.06807
maximum resident set size= 474592
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 233217
page faults= 0
swaps= 0
block input operations= 68424
block output operations= 66064
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 86
involuntary context switches= 1324

runsolver used 0.036002 second user time and 0.100006 second system time

The end