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/dist-upgrade/real/e381ba7e-a192-11e0-8647-00163e1e087d.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/real/e381ba7e-a192-11e0-8647-00163e1e087d.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/dist-upgrade/real/e381ba7e-a192-11e0-8647-00163e1e087d.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.05 1.06 1.06 2/64 13253
/proc/meminfo: memFree=287248/1022884 swapFree=0/0
[pid=13253] ppid=13252 vsize=3152 CPUtime=0
/proc/13253/stat : 13253 (runsolver) R 13252 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 118022255 3227648 32 18446744073709551615 134512640 134586868 4290562240 4290560288 4152173616 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/13253/statm: 788 32 0 19 0 73 0

[startup+0.199175 s]
/proc/loadavg: 1.05 1.06 1.06 2/64 13253
/proc/meminfo: memFree=287248/1022884 swapFree=0/0
[pid=13253] ppid=13252 vsize=9212 CPUtime=0.02
/proc/13253/stat : 13253 (aspuncud-full) S 13252 13253 1745 0 -1 4202496 694 2812 0 0 0 0 1 1 20 0 1 0 118022255 9433088 364 18446744073709551615 4194304 5129932 140735247141936 140735247140592 140391211590750 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13253/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200279 s]
/proc/loadavg: 1.05 1.06 1.06 2/64 13253
/proc/meminfo: memFree=287248/1022884 swapFree=0/0
[pid=13253] ppid=13252 vsize=9212 CPUtime=0.02
/proc/13253/stat : 13253 (aspuncud-full) S 13252 13253 1745 0 -1 4202496 694 2812 0 0 0 0 1 1 20 0 1 0 118022255 9433088 364 18446744073709551615 4194304 5129932 140735247141936 140735247140592 140391211590750 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13253/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300232 s]
/proc/loadavg: 1.05 1.06 1.06 2/64 13253
/proc/meminfo: memFree=287248/1022884 swapFree=0/0
[pid=13253] ppid=13252 vsize=9212 CPUtime=0.02
/proc/13253/stat : 13253 (aspuncud-full) S 13252 13253 1745 0 -1 4202496 694 2812 0 0 0 0 1 1 20 0 1 0 118022255 9433088 364 18446744073709551615 4194304 5129932 140735247141936 140735247140592 140391211590750 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13253/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700238 s]
/proc/loadavg: 1.05 1.06 1.06 2/64 13253
/proc/meminfo: memFree=287248/1022884 swapFree=0/0
[pid=13253] ppid=13252 vsize=9212 CPUtime=0.02
/proc/13253/stat : 13253 (aspuncud-full) S 13252 13253 1745 0 -1 4202496 694 2812 0 0 0 0 1 1 20 0 1 0 118022255 9433088 364 18446744073709551615 4194304 5129932 140735247141936 140735247140592 140391211590750 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13253/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50045 s]
/proc/loadavg: 1.04 1.06 1.06 1/66 13266
/proc/meminfo: memFree=249148/1022884 swapFree=0/0
[pid=13253] ppid=13252 vsize=9212 CPUtime=0.02
/proc/13253/stat : 13253 (aspuncud-full) S 13252 13253 1745 0 -1 4202496 694 2812 0 0 0 0 1 1 20 0 1 0 118022255 9433088 364 18446744073709551615 4194304 5129932 140735247141936 140735247140592 140391211590750 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13253/statm: 2303 364 303 229 0 63 0
[pid=13266] ppid=13253 vsize=53200 CPUtime=1.35
/proc/13266/stat : 13266 (cudf2lp) D 13253 13253 1745 0 -1 4202496 14947 0 0 0 131 4 0 0 20 0 1 0 118022257 54476800 11549 18446744073709551615 4194304 5690517 140733673729792 140733673727464 5058400 0 0 16781316 0 0 0 0 17 0 0 0 9 0 0
/proc/13266/statm: 13300 11549 160 366 0 12931 0
Current children cumulated CPU time (s) 1.37
Current children cumulated vsize (KiB) 62412

[startup+3.10022 s]
/proc/loadavg: 1.04 1.06 1.06 2/66 13266
/proc/meminfo: memFree=184520/1022884 swapFree=0/0
[pid=13253] ppid=13252 vsize=9212 CPUtime=2.45
/proc/13253/stat : 13253 (aspuncud-full) S 13252 13253 1745 0 -1 4202496 721 28020 0 0 0 0 231 14 20 0 1 0 118022255 9433088 364 18446744073709551615 4194304 5129932 140735247141936 140735247140592 140391211590750 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13253/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 2.45
Current children cumulated vsize (KiB) 9212
heavy processes:

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

[startup+3.20363 s]
/proc/loadavg: 1.04 1.06 1.06 2/66 13267
/proc/meminfo: memFree=239684/1022884 swapFree=0/0
[pid=13253] ppid=13252 vsize=9212 CPUtime=2.45
/proc/13253/stat : 13253 (aspuncud-full) S 13252 13253 1745 0 -1 4202496 721 28020 0 0 0 0 231 14 20 0 1 0 118022255 9433088 364 18446744073709551615 4194304 5129932 140735247141936 140735247140592 140391211590750 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13253/statm: 2303 364 303 229 0 63 0
[pid=13267] ppid=13253 vsize=30488 CPUtime=0.59
/proc/13267/stat : 13267 (gringo) R 13253 13253 1745 0 -1 4202496 7565 0 0 0 57 2 0 0 20 0 1 0 118022514 31219712 6454 18446744073709551615 4194304 6531320 140737469580144 140737469576328 5554426 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13267/statm: 7622 6454 259 571 0 7043 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 39700

[startup+4.80026 s]
/proc/loadavg: 1.04 1.06 1.06 2/66 13267
/proc/meminfo: memFree=118784/1022884 swapFree=0/0
[pid=13253] ppid=13252 vsize=9212 CPUtime=2.45
/proc/13253/stat : 13253 (aspuncud-full) S 13252 13253 1745 0 -1 4202496 721 28020 0 0 0 0 231 14 20 0 1 0 118022255 9433088 364 18446744073709551615 4194304 5129932 140735247141936 140735247140592 140391211590750 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13253/statm: 2303 364 303 229 0 63 0
[pid=13267] ppid=13253 vsize=211120 CPUtime=2.18
/proc/13267/stat : 13267 (gringo) R 13253 13253 1745 0 -1 4202496 48611 0 0 0 202 16 0 0 20 0 1 0 118022514 216186880 44426 18446744073709551615 4194304 6531320 140737469580144 140737469576952 4344262 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13267/statm: 52780 44426 283 571 0 52201 0
Current children cumulated CPU time (s) 4.63
Current children cumulated vsize (KiB) 220332

[startup+5.60458 s]
/proc/loadavg: 1.04 1.06 1.06 1/66 13270
/proc/meminfo: memFree=254540/1022884 swapFree=0/0
[pid=13253] ppid=13252 vsize=9212 CPUtime=5.23
/proc/13253/stat : 13253 (aspuncud-full) S 13252 13253 1745 0 -1 4202496 794 95950 0 0 0 0 479 44 20 0 1 0 118022255 9433088 364 18446744073709551615 4194304 5129932 140735247141936 140735247139488 140391211590750 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13253/statm: 2303 364 303 229 0 63 0
[pid=13270] ppid=13253 vsize=4060 CPUtime=0
/proc/13270/stat : 13270 (rm) D 13253 13253 1745 0 -1 4202496 211 0 0 0 0 0 0 0 20 0 1 0 118022794 4157440 143 18446744073709551615 4194304 4250524 140733886903872 140733886903096 140437718301213 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/13270/statm: 1015 143 119 14 0 67 0
Current children cumulated CPU time (s) 5.23
Current children cumulated vsize (KiB) 13272

[startup+6.0004 s]
/proc/loadavg: 1.04 1.06 1.06 1/66 13270
/proc/meminfo: memFree=254540/1022884 swapFree=0/0
[pid=13253] ppid=13252 vsize=9212 CPUtime=5.23
/proc/13253/stat : 13253 (aspuncud-full) S 13252 13253 1745 0 -1 4202496 794 95950 0 0 0 0 479 44 20 0 1 0 118022255 9433088 364 18446744073709551615 4194304 5129932 140735247141936 140735247139488 140391211590750 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13253/statm: 2303 364 303 229 0 63 0
[pid=13270] ppid=13253 vsize=4060 CPUtime=0
/proc/13270/stat : 13270 (rm) D 13253 13253 1745 0 -1 4202496 211 0 0 0 0 0 0 0 20 0 1 0 118022794 4157440 143 18446744073709551615 4194304 4250524 140733886903872 140733886903096 140437718301213 0 0 16781316 0 0 0 0 17 0 0 0 59 0 0
/proc/13270/statm: 1015 143 119 14 0 67 0
Current children cumulated CPU time (s) 5.23
Current children cumulated vsize (KiB) 13272

[startup+6.20037 s]
/proc/loadavg: 1.04 1.06 1.06 1/66 13270
/proc/meminfo: memFree=254540/1022884 swapFree=0/0
[pid=13253] ppid=13252 vsize=9212 CPUtime=5.23
/proc/13253/stat : 13253 (aspuncud-full) S 13252 13253 1745 0 -1 4202496 794 95950 0 0 0 0 479 44 20 0 1 0 118022255 9433088 364 18446744073709551615 4194304 5129932 140735247141936 140735247139488 140391211590750 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13253/statm: 2303 364 303 229 0 63 0
[pid=13270] ppid=13253 vsize=4060 CPUtime=0
/proc/13270/stat : 13270 (rm) D 13253 13253 1745 0 -1 4202496 211 0 0 0 0 0 0 0 20 0 1 0 118022794 4157440 143 18446744073709551615 4194304 4250524 140733886903872 140733886903096 140437718301213 0 0 16781316 0 0 0 0 17 0 0 0 68 0 0
/proc/13270/statm: 1015 143 119 14 0 67 0
Current children cumulated CPU time (s) 5.23
Current children cumulated vsize (KiB) 13272

Child status: 0
Real time (s): 6.27374
CPU time (s): 5.24833
CPU user time (s): 4.7963
CPU system time (s): 0.452028
CPU usage (%): 83.6554
Max. virtual memory (cumulated for all children) (KiB): 220332

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.7963
system time used= 0.452028
maximum resident set size= 177704
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 96979
page faults= 0
swaps= 0
block input operations= 37056
block output operations= 25264
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 115
involuntary context switches= 648

runsolver used 0.012 second user time and 0.032002 second system time

The end