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/upgrade/install/rand7.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/install/rand7.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/upgrade/install/rand7.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

[startup+0 s]
/proc/loadavg: 1.07 0.95 0.57 2/65 9193
/proc/meminfo: memFree=563840/1022884 swapFree=0/0
[pid=9193] ppid=9192 vsize=3152 CPUtime=0
/proc/9193/stat : 9193 (runsolver) R 9192 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 117116856 3227648 32 18446744073709551615 134512640 134586868 4291416848 4291414896 4152120368 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/9193/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.165641 s]
/proc/loadavg: 1.07 0.95 0.57 2/65 9193
/proc/meminfo: memFree=563840/1022884 swapFree=0/0
[pid=9193] ppid=9192 vsize=9212 CPUtime=0.04
/proc/9193/stat : 9193 (aspuncud-full) S 9192 9193 1745 0 -1 4202496 702 2797 2 7 0 0 3 1 20 0 1 0 117116856 9433088 365 18446744073709551615 4194304 5129932 140735994831472 140735994830128 140530113352798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9193/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200336 s]
/proc/loadavg: 1.07 0.95 0.57 2/65 9193
/proc/meminfo: memFree=563840/1022884 swapFree=0/0
[pid=9193] ppid=9192 vsize=9212 CPUtime=0.04
/proc/9193/stat : 9193 (aspuncud-full) S 9192 9193 1745 0 -1 4202496 702 2797 2 7 0 0 3 1 20 0 1 0 117116856 9433088 365 18446744073709551615 4194304 5129932 140735994831472 140735994830128 140530113352798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9193/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.30032 s]
/proc/loadavg: 1.07 0.95 0.57 2/65 9193
/proc/meminfo: memFree=563840/1022884 swapFree=0/0
[pid=9193] ppid=9192 vsize=9212 CPUtime=0.04
/proc/9193/stat : 9193 (aspuncud-full) S 9192 9193 1745 0 -1 4202496 702 2797 2 7 0 0 3 1 20 0 1 0 117116856 9433088 365 18446744073709551615 4194304 5129932 140735994831472 140735994830128 140530113352798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9193/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700236 s]
/proc/loadavg: 1.07 0.95 0.57 2/65 9193
/proc/meminfo: memFree=563840/1022884 swapFree=0/0
[pid=9193] ppid=9192 vsize=9212 CPUtime=0.04
/proc/9193/stat : 9193 (aspuncud-full) S 9192 9193 1745 0 -1 4202496 702 2797 2 7 0 0 3 1 20 0 1 0 117116856 9433088 365 18446744073709551615 4194304 5129932 140735994831472 140735994830128 140530113352798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9193/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 1.07 0.95 0.57 2/67 9206
/proc/meminfo: memFree=528724/1022884 swapFree=0/0
[pid=9193] ppid=9192 vsize=9212 CPUtime=0.04
/proc/9193/stat : 9193 (aspuncud-full) S 9192 9193 1745 0 -1 4202496 702 2797 2 7 0 0 3 1 20 0 1 0 117116856 9433088 365 18446744073709551615 4194304 5129932 140735994831472 140735994830128 140530113352798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9193/statm: 2303 365 303 229 0 63 0
[pid=9206] ppid=9193 vsize=31912 CPUtime=1.28
/proc/9206/stat : 9206 (cudf2lp) R 9193 9193 1745 0 -1 4202496 9383 0 1 0 124 4 0 0 20 0 1 0 117116868 32677888 7651 18446744073709551615 4194304 5690517 140736565892848 140736565890488 4970418 0 0 16781316 0 0 0 0 17 0 0 0 7 0 0
/proc/9206/statm: 7978 7651 160 366 0 7609 0
Current children cumulated CPU time (s) 1.32
Current children cumulated vsize (KiB) 41124

[startup+3.10033 s]
/proc/loadavg: 1.07 0.95 0.57 2/67 9206
/proc/meminfo: memFree=495988/1022884 swapFree=0/0
[pid=9193] ppid=9192 vsize=9212 CPUtime=0.04
/proc/9193/stat : 9193 (aspuncud-full) S 9192 9193 1745 0 -1 4202496 702 2797 2 7 0 0 3 1 20 0 1 0 117116856 9433088 365 18446744073709551615 4194304 5129932 140735994831472 140735994830128 140530113352798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9193/statm: 2303 365 303 229 0 63 0
[pid=9206] ppid=9193 vsize=108108 CPUtime=2.87
/proc/9206/stat : 9206 (cudf2lp) R 9193 9193 1745 0 -1 4202496 26294 0 1 0 275 12 0 0 20 0 1 0 117116868 110702592 22897 18446744073709551615 4194304 5690517 140736565892848 140736565889000 4963881 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/9206/statm: 27027 22897 160 366 0 26658 0
Current children cumulated CPU time (s) 2.91
Current children cumulated vsize (KiB) 117320

[startup+6.30024 s]
/proc/loadavg: 1.06 0.95 0.57 2/67 9206
/proc/meminfo: memFree=477884/1022884 swapFree=0/0
[pid=9193] ppid=9192 vsize=9212 CPUtime=5.27
/proc/9193/stat : 9193 (aspuncud-full) S 9192 9193 1745 0 -1 4202496 731 44074 2 8 0 0 500 27 20 0 1 0 117116856 9433088 365 18446744073709551615 4194304 5129932 140735994831472 140735994830128 140530113352798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9193/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 5.27
Current children cumulated vsize (KiB) 9212

[startup+12.7003 s]
/proc/loadavg: 1.06 0.95 0.57 2/67 9207
/proc/meminfo: memFree=125972/1022884 swapFree=0/0
[pid=9193] ppid=9192 vsize=9212 CPUtime=5.27
/proc/9193/stat : 9193 (aspuncud-full) S 9192 9193 1745 0 -1 4202496 731 44074 2 8 0 0 500 27 20 0 1 0 117116856 9433088 365 18446744073709551615 4194304 5129932 140735994831472 140735994830128 140530113352798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9193/statm: 2303 365 303 229 0 63 0
[pid=9207] ppid=9193 vsize=536648 CPUtime=7.09
/proc/9207/stat : 9207 (gringo) R 9193 9193 1745 0 -1 4202496 126330 0 1 0 663 46 0 0 20 0 1 0 117117408 549527552 107834 18446744073709551615 4194304 6531320 140736248939648 140736248936264 4596143 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/9207/statm: 134162 107834 282 571 0 133583 0
Current children cumulated CPU time (s) 12.36
Current children cumulated vsize (KiB) 545860

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

[startup+12.8003 s]
/proc/loadavg: 1.06 0.95 0.57 2/67 9207
/proc/meminfo: memFree=125972/1022884 swapFree=0/0
[pid=9193] ppid=9192 vsize=9212 CPUtime=5.27
/proc/9193/stat : 9193 (aspuncud-full) S 9192 9193 1745 0 -1 4202496 731 44074 2 8 0 0 500 27 20 0 1 0 117116856 9433088 365 18446744073709551615 4194304 5129932 140735994831472 140735994830128 140530113352798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9193/statm: 2303 365 303 229 0 63 0
[pid=9207] ppid=9193 vsize=553332 CPUtime=7.2
/proc/9207/stat : 9207 (gringo) R 9193 9193 1745 0 -1 4202496 130166 0 1 0 673 47 0 0 20 0 1 0 117117408 566611968 111670 18446744073709551615 4194304 6531320 140736248939648 140736248935576 4597961 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/9207/statm: 138333 111670 282 571 0 137754 0
Current children cumulated CPU time (s) 12.47
Current children cumulated vsize (KiB) 562544

[startup+14.4035 s]
/proc/loadavg: 1.05 0.96 0.58 2/68 9209
/proc/meminfo: memFree=335400/1022884 swapFree=0/0
[pid=9193] ppid=9192 vsize=9212 CPUtime=13.32
/proc/9193/stat : 9193 (aspuncud-full) S 9192 9193 1745 0 -1 4202496 773 179729 2 9 0 0 1243 89 20 0 1 0 117116856 9433088 365 18446744073709551615 4194304 5129932 140735994831472 140735994829536 140530113352798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9193/statm: 2303 365 303 229 0 63 0
[pid=9208] ppid=9193 vsize=165572 CPUtime=0.72
/proc/9208/stat : 9208 (unclasp) R 9193 9193 1745 0 -1 4202496 45914 0 0 0 60 12 0 0 20 0 1 0 117118222 169545728 39680 18446744073709551615 4194304 6012874 140736750217536 140736750216120 4646425 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/9208/statm: 41393 39680 188 444 0 40941 0
[pid=9209] ppid=9193 vsize=22040 CPUtime=0
/proc/9209/stat : 9209 (parse.py) S 9193 9193 1745 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 117118222 22568960 1128 18446744073709551615 4194304 6642060 140737061471744 140737061470104 140579570444064 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9209/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 14.04
Current children cumulated vsize (KiB) 196824

[startup+14.8003 s]
/proc/loadavg: 1.05 0.96 0.58 2/68 9209
/proc/meminfo: memFree=335400/1022884 swapFree=0/0
[pid=9193] ppid=9192 vsize=9212 CPUtime=13.32
/proc/9193/stat : 9193 (aspuncud-full) S 9192 9193 1745 0 -1 4202496 773 179729 2 9 0 0 1243 89 20 0 1 0 117116856 9433088 365 18446744073709551615 4194304 5129932 140735994831472 140735994829536 140530113352798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9193/statm: 2303 365 303 229 0 63 0
[pid=9208] ppid=9193 vsize=158012 CPUtime=1.12
/proc/9208/stat : 9208 (unclasp) R 9193 9193 1745 0 -1 4202496 47149 0 0 0 100 12 0 0 20 0 1 0 117118222 161804288 38647 18446744073709551615 4194304 6012874 140736750217536 140736750216712 5251088 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/9208/statm: 39503 38647 225 444 0 39051 0
[pid=9209] ppid=9193 vsize=22188 CPUtime=0
/proc/9209/stat : 9209 (parse.py) S 9193 9193 1745 0 -1 4202496 1331 0 0 0 0 0 0 0 20 0 1 0 117118222 22720512 1140 18446744073709551615 4194304 6642060 140737061471744 140737061469784 140579570444064 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9209/statm: 5547 1140 508 598 0 633 0
Current children cumulated CPU time (s) 14.44
Current children cumulated vsize (KiB) 189412

[startup+15.2003 s]
/proc/loadavg: 1.05 0.96 0.58 2/68 9209
/proc/meminfo: memFree=335400/1022884 swapFree=0/0
[pid=9193] ppid=9192 vsize=9212 CPUtime=14.63
/proc/9193/stat : 9193 (aspuncud-full) S 9192 9193 1745 0 -1 4202496 807 228270 2 9 0 0 1357 106 20 0 1 0 117116856 9433088 365 18446744073709551615 4194304 5129932 140735994831472 140735994829024 140530113352798 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9193/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 14.63
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 15.2081
CPU time (s): 14.6649
CPU user time (s): 13.5808
CPU system time (s): 1.08407
CPU usage (%): 96.4286
Max. virtual memory (cumulated for all children) (KiB): 587548

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.5808
system time used= 1.08407
maximum resident set size= 468620
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 229313
page faults= 11
swaps= 0
block input operations= 69192
block output operations= 65344
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 171
involuntary context switches= 1766

runsolver used 0.024001 second user time and 0.076004 second system time

The end