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/dist-upgrade/install/rand242.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand242.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/dist-upgrade/install/rand242.cudf.result -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: 1.07 1.09 1.05 2/64 17581
/proc/meminfo: memFree=760992/1022884 swapFree=0/0
[pid=17581] ppid=17580 vsize=3152 CPUtime=0
/proc/17581/stat : 17581 (runsolver) D 17580 17581 32685 0 -1 4202560 75 0 0 0 0 0 0 0 20 0 1 0 39687165 3227648 96 18446744073709551615 134512640 134586868 4289655440 4289653488 4151923760 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/17581/statm: 788 96 64 19 0 73 0

[startup+0.14531 s]
/proc/loadavg: 1.07 1.09 1.05 2/64 17581
/proc/meminfo: memFree=760992/1022884 swapFree=0/0
[pid=17581] ppid=17580 vsize=9212 CPUtime=0.05
/proc/17581/stat : 17581 (aspcud-full) S 17580 17581 32685 0 -1 4202496 679 3079 2 5 1 0 3 1 20 0 1 0 39687165 9433088 365 18446744073709551615 4194304 5129932 140737187074544 140737187073200 140028014519390 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17581/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200374 s]
/proc/loadavg: 1.07 1.09 1.05 2/64 17581
/proc/meminfo: memFree=760992/1022884 swapFree=0/0
[pid=17581] ppid=17580 vsize=9212 CPUtime=0.06
/proc/17581/stat : 17581 (aspcud-full) S 17580 17581 32685 0 -1 4202496 733 3611 2 7 1 0 4 1 20 0 1 0 39687165 9433088 365 18446744073709551615 4194304 5129932 140737187074544 140737187073200 140028014519390 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17581/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.300377 s]
/proc/loadavg: 1.07 1.09 1.05 2/64 17581
/proc/meminfo: memFree=760992/1022884 swapFree=0/0
[pid=17581] ppid=17580 vsize=9212 CPUtime=0.06
/proc/17581/stat : 17581 (aspcud-full) S 17580 17581 32685 0 -1 4202496 733 3611 2 7 1 0 4 1 20 0 1 0 39687165 9433088 365 18446744073709551615 4194304 5129932 140737187074544 140737187073200 140028014519390 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17581/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.700258 s]
/proc/loadavg: 1.07 1.09 1.05 2/64 17581
/proc/meminfo: memFree=760992/1022884 swapFree=0/0
[pid=17581] ppid=17580 vsize=9212 CPUtime=0.06
/proc/17581/stat : 17581 (aspcud-full) S 17580 17581 32685 0 -1 4202496 733 3611 2 7 1 0 4 1 20 0 1 0 39687165 9433088 365 18446744073709551615 4194304 5129932 140737187074544 140737187073200 140028014519390 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17581/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 1.07 1.09 1.05 2/66 17597
/proc/meminfo: memFree=727116/1022884 swapFree=0/0
[pid=17581] ppid=17580 vsize=9212 CPUtime=0.06
/proc/17581/stat : 17581 (aspcud-full) S 17580 17581 32685 0 -1 4202496 733 3611 2 7 1 0 4 1 20 0 1 0 39687165 9433088 365 18446744073709551615 4194304 5129932 140737187074544 140737187073200 140028014519390 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17581/statm: 2303 365 303 229 0 63 0
[pid=17597] ppid=17581 vsize=30328 CPUtime=1.25
/proc/17597/stat : 17597 (cudf2lp) R 17581 17581 32685 0 -1 4202496 8820 0 10 0 121 4 0 0 20 0 1 0 39687182 31055872 7097 18446744073709551615 4194304 5690517 140735158432880 140735158430536 4293705 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/17597/statm: 7582 7097 159 366 0 7213 0
Current children cumulated CPU time (s) 1.31
Current children cumulated vsize (KiB) 39540

[startup+3.10036 s]
/proc/loadavg: 1.07 1.09 1.05 2/66 17597
/proc/meminfo: memFree=694504/1022884 swapFree=0/0
[pid=17581] ppid=17580 vsize=9212 CPUtime=0.06
/proc/17581/stat : 17581 (aspcud-full) S 17580 17581 32685 0 -1 4202496 733 3611 2 7 1 0 4 1 20 0 1 0 39687165 9433088 365 18446744073709551615 4194304 5129932 140737187074544 140737187073200 140028014519390 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17581/statm: 2303 365 303 229 0 63 0
[pid=17597] ppid=17581 vsize=58508 CPUtime=2.83
/proc/17597/stat : 17597 (cudf2lp) R 17581 17581 32685 0 -1 4202496 17754 0 10 0 275 8 0 0 20 0 1 0 39687182 59912192 14366 18446744073709551615 4194304 5690517 140735158432880 140735158430520 4360746 0 0 16781316 0 0 0 0 17 0 0 0 7 0 0
/proc/17597/statm: 14627 14366 160 366 0 14258 0
Current children cumulated CPU time (s) 2.89
Current children cumulated vsize (KiB) 67720

[startup+6.30025 s]
/proc/loadavg: 1.07 1.09 1.05 1/66 17598
/proc/meminfo: memFree=709756/1022884 swapFree=0/0
[pid=17581] ppid=17580 vsize=9212 CPUtime=5.22
/proc/17581/stat : 17581 (aspcud-full) S 17580 17581 32685 0 -1 4202496 759 44878 2 17 1 0 495 26 20 0 1 0 39687165 9433088 365 18446744073709551615 4194304 5129932 140737187074544 140737187073200 140028014519390 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17581/statm: 2303 365 303 229 0 63 0
[pid=17598] ppid=17581 vsize=35172 CPUtime=0.7
/proc/17598/stat : 17598 (gringo) R 17581 17581 32685 0 -1 4202496 9978 0 22 0 64 6 0 0 20 0 1 0 39687712 36016128 6867 18446744073709551615 4194304 6531320 140734954558864 140734954555048 4348457 0 0 16781316 16386 0 0 0 17 0 0 0 11 0 0
/proc/17598/statm: 8793 6867 259 571 0 8214 0
Current children cumulated CPU time (s) 5.92
Current children cumulated vsize (KiB) 44384

[startup+12.7004 s]
/proc/loadavg: 1.06 1.09 1.05 1/67 17600
/proc/meminfo: memFree=687056/1022884 swapFree=0/0
[pid=17581] ppid=17580 vsize=9212 CPUtime=11.63
/proc/17581/stat : 17581 (aspcud-full) S 17580 17581 32685 0 -1 4202496 799 180549 2 40 1 0 1074 88 20 0 1 0 39687165 9433088 365 18446744073709551615 4194304 5129932 140737187074544 140737187072608 140028014519390 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17581/statm: 2303 365 303 229 0 63 0
[pid=17599] ppid=17581 vsize=105776 CPUtime=0.49
/proc/17599/stat : 17599 (clasp) R 17581 17581 32685 0 -1 4202496 29580 0 22 0 40 9 0 0 20 0 1 0 39688368 108314624 25417 18446744073709551615 4194304 6238623 140736932657408 140736932652904 5449417 0 0 16781316 18946 0 0 0 17 0 0 0 16 0 0
/proc/17599/statm: 26444 25417 198 500 0 25941 0
[pid=17600] ppid=17581 vsize=22040 CPUtime=0
/proc/17600/stat : 17600 (parse.py) S 17581 17581 32685 0 -1 4202496 1316 0 1 0 0 0 0 0 20 0 1 0 39688368 22568960 1127 18446744073709551615 4194304 6642060 140735184497056 140735184495416 140023783524128 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17600/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 12.12
Current children cumulated vsize (KiB) 137028

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

[startup+12.8005 s]
/proc/loadavg: 1.06 1.09 1.05 1/67 17600
/proc/meminfo: memFree=687056/1022884 swapFree=0/0
[pid=17581] ppid=17580 vsize=9212 CPUtime=11.63
/proc/17581/stat : 17581 (aspcud-full) S 17580 17581 32685 0 -1 4202496 799 180549 2 40 1 0 1074 88 20 0 1 0 39687165 9433088 365 18446744073709551615 4194304 5129932 140737187074544 140737187072608 140028014519390 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17581/statm: 2303 365 303 229 0 63 0
[pid=17599] ppid=17581 vsize=125436 CPUtime=0.58
/proc/17599/stat : 17599 (clasp) R 17581 17581 32685 0 -1 4202496 34948 0 22 0 48 10 0 0 20 0 1 0 39688368 128446464 30785 18446744073709551615 4194304 6238623 140736932657408 140736932652904 4541408 0 0 16781316 18946 0 0 0 17 0 0 0 16 0 0
/proc/17599/statm: 31359 30785 198 500 0 30856 0
[pid=17600] ppid=17581 vsize=22040 CPUtime=0
/proc/17600/stat : 17600 (parse.py) S 17581 17581 32685 0 -1 4202496 1316 0 1 0 0 0 0 0 20 0 1 0 39688368 22568960 1127 18446744073709551615 4194304 6642060 140735184497056 140735184495416 140023783524128 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17600/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 12.21
Current children cumulated vsize (KiB) 156688

[startup+14.4093 s]
/proc/loadavg: 1.06 1.09 1.05 2/67 17600
/proc/meminfo: memFree=528460/1022884 swapFree=0/0
[pid=17581] ppid=17580 vsize=9212 CPUtime=11.63
/proc/17581/stat : 17581 (aspcud-full) S 17580 17581 32685 0 -1 4202496 799 180549 2 40 1 0 1074 88 20 0 1 0 39687165 9433088 365 18446744073709551615 4194304 5129932 140737187074544 140737187072608 140028014519390 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17581/statm: 2303 365 303 229 0 63 0
[pid=17599] ppid=17581 vsize=161524 CPUtime=2.18
/proc/17599/stat : 17599 (clasp) R 17581 17581 32685 0 -1 4202496 48002 0 22 0 202 16 0 0 20 0 1 0 39688368 165400576 39523 18446744073709551615 4194304 6238623 140736932657408 140736932654432 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 16 0 0
/proc/17599/statm: 40381 39523 263 500 0 39878 0
[pid=17600] ppid=17581 vsize=22040 CPUtime=0
/proc/17600/stat : 17600 (parse.py) S 17581 17581 32685 0 -1 4202496 1316 0 1 0 0 0 0 0 20 0 1 0 39688368 22568960 1127 18446744073709551615 4194304 6642060 140735184497056 140735184495416 140023783524128 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17600/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 13.81
Current children cumulated vsize (KiB) 192776

[startup+16.0004 s]
/proc/loadavg: 1.06 1.09 1.05 2/67 17600
/proc/meminfo: memFree=528460/1022884 swapFree=0/0
[pid=17581] ppid=17580 vsize=9212 CPUtime=11.63
/proc/17581/stat : 17581 (aspcud-full) S 17580 17581 32685 0 -1 4202496 799 180549 2 40 1 0 1074 88 20 0 1 0 39687165 9433088 365 18446744073709551615 4194304 5129932 140737187074544 140737187072608 140028014519390 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17581/statm: 2303 365 303 229 0 63 0
[pid=17599] ppid=17581 vsize=161524 CPUtime=3.76
/proc/17599/stat : 17599 (clasp) R 17581 17581 32685 0 -1 4202496 48003 0 22 0 360 16 0 0 20 0 1 0 39688368 165400576 39524 18446744073709551615 4194304 6238623 140736932657408 140736932654432 4676760 0 0 16781316 18946 0 0 0 17 0 0 0 16 0 0
/proc/17599/statm: 40381 39524 264 500 0 39878 0
[pid=17600] ppid=17581 vsize=22040 CPUtime=0
/proc/17600/stat : 17600 (parse.py) S 17581 17581 32685 0 -1 4202496 1316 0 1 0 0 0 0 0 20 0 1 0 39688368 22568960 1127 18446744073709551615 4194304 6642060 140735184497056 140735184495416 140023783524128 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17600/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 15.39
Current children cumulated vsize (KiB) 192776

[startup+16.4004 s]
/proc/loadavg: 1.06 1.09 1.05 2/67 17600
/proc/meminfo: memFree=528460/1022884 swapFree=0/0
[pid=17581] ppid=17580 vsize=9212 CPUtime=11.63
/proc/17581/stat : 17581 (aspcud-full) S 17580 17581 32685 0 -1 4202496 799 180549 2 40 1 0 1074 88 20 0 1 0 39687165 9433088 365 18446744073709551615 4194304 5129932 140737187074544 140737187072608 140028014519390 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17581/statm: 2303 365 303 229 0 63 0
[pid=17599] ppid=17581 vsize=161524 CPUtime=4.16
/proc/17599/stat : 17599 (clasp) R 17581 17581 32685 0 -1 4202496 48003 0 22 0 400 16 0 0 20 0 1 0 39688368 165400576 39524 18446744073709551615 4194304 6238623 140736932657408 140736932654432 4677084 0 0 16781316 18946 0 0 0 17 0 0 0 16 0 0
/proc/17599/statm: 40381 39524 264 500 0 39878 0
[pid=17600] ppid=17581 vsize=22040 CPUtime=0
/proc/17600/stat : 17600 (parse.py) S 17581 17581 32685 0 -1 4202496 1316 0 1 0 0 0 0 0 20 0 1 0 39688368 22568960 1127 18446744073709551615 4194304 6642060 140735184497056 140735184495416 140023783524128 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17600/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 15.79
Current children cumulated vsize (KiB) 192776

[startup+16.8005 s]
/proc/loadavg: 1.13 1.10 1.06 2/67 17600
/proc/meminfo: memFree=528460/1022884 swapFree=0/0
[pid=17581] ppid=17580 vsize=9212 CPUtime=16.14
/proc/17581/stat : 17581 (aspcud-full) S 17580 17581 32685 0 -1 4202496 834 229903 2 64 1 0 1502 111 20 0 1 0 39687165 9433088 365 18446744073709551615 4194304 5129932 140737187074544 140737187072096 140028014519390 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17581/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 16.14
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 16.8277
CPU time (s): 16.169
CPU user time (s): 15.0409
CPU system time (s): 1.12807
CPU usage (%): 96.0859
Max. virtual memory (cumulated for all children) (KiB): 589272

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 15.0409
system time used= 1.12807
maximum resident set size= 468772
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 230971
page faults= 67
swaps= 0
block input operations= 77952
block output operations= 65320
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 174
involuntary context switches= 304

runsolver used 0.036002 second user time and 0.088005 second system time

The end