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/upgrade/easy/rand695.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand695.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/upgrade/upgrade/easy/rand695.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.98 0.73 0.34 2/60 9375
/proc/meminfo: memFree=279468/1022884 swapFree=0/0
[pid=9375] ppid=9374 vsize=3152 CPUtime=0
/proc/9375/stat : 9375 (runsolver) R 9374 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 117081053 3227648 32 18446744073709551615 134512640 134586868 4289246864 4289244912 4151469104 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/9375/statm: 788 32 0 19 0 73 0

[startup+0.195722 s]
/proc/loadavg: 0.98 0.73 0.34 2/60 9375
/proc/meminfo: memFree=279468/1022884 swapFree=0/0
[pid=9375] ppid=9374 vsize=9212 CPUtime=0.05
/proc/9375/stat : 9375 (aspcud-full) S 9374 9375 1750 0 -1 4202496 739 3606 2 7 0 0 3 2 20 0 1 0 117081053 9433088 365 18446744073709551615 4194304 5129932 140733830911904 140733830910560 140480343413854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9375/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.200437 s]
/proc/loadavg: 0.98 0.73 0.34 2/60 9375
/proc/meminfo: memFree=279468/1022884 swapFree=0/0
[pid=9375] ppid=9374 vsize=9212 CPUtime=0.05
/proc/9375/stat : 9375 (aspcud-full) S 9374 9375 1750 0 -1 4202496 739 3606 2 7 0 0 3 2 20 0 1 0 117081053 9433088 365 18446744073709551615 4194304 5129932 140733830911904 140733830910560 140480343413854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9375/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.300236 s]
/proc/loadavg: 0.98 0.73 0.34 2/60 9375
/proc/meminfo: memFree=279468/1022884 swapFree=0/0
[pid=9375] ppid=9374 vsize=9212 CPUtime=0.05
/proc/9375/stat : 9375 (aspcud-full) S 9374 9375 1750 0 -1 4202496 739 3606 2 7 0 0 3 2 20 0 1 0 117081053 9433088 365 18446744073709551615 4194304 5129932 140733830911904 140733830910560 140480343413854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9375/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 9212

[startup+0.700237 s]
/proc/loadavg: 0.98 0.73 0.34 2/60 9375
/proc/meminfo: memFree=279468/1022884 swapFree=0/0
[pid=9375] ppid=9374 vsize=9212 CPUtime=0.05
/proc/9375/stat : 9375 (aspcud-full) S 9374 9375 1750 0 -1 4202496 739 3606 2 7 0 0 3 2 20 0 1 0 117081053 9433088 365 18446744073709551615 4194304 5129932 140733830911904 140733830910560 140480343413854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9375/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.98 0.74 0.35 2/62 9391
/proc/meminfo: memFree=245220/1022884 swapFree=0/0
[pid=9375] ppid=9374 vsize=9212 CPUtime=0.05
/proc/9375/stat : 9375 (aspcud-full) S 9374 9375 1750 0 -1 4202496 739 3606 2 7 0 0 3 2 20 0 1 0 117081053 9433088 365 18446744073709551615 4194304 5129932 140733830911904 140733830910560 140480343413854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9375/statm: 2303 365 303 229 0 63 0
[pid=9391] ppid=9375 vsize=54580 CPUtime=1.18
/proc/9391/stat : 9391 (cudf2lp) R 9375 9375 1750 0 -1 4202496 12980 0 1 0 114 4 0 0 20 0 1 0 117081068 55889920 11247 18446744073709551615 4194304 5690517 140736301849792 140736301845992 4363370 0 0 16781316 0 0 0 0 17 0 0 0 15 0 0
/proc/9391/statm: 13645 11247 159 366 0 13276 0
Current children cumulated CPU time (s) 1.23
Current children cumulated vsize (KiB) 63792

[startup+3.10033 s]
/proc/loadavg: 0.98 0.74 0.35 2/62 9391
/proc/meminfo: memFree=211864/1022884 swapFree=0/0
[pid=9375] ppid=9374 vsize=9212 CPUtime=0.05
/proc/9375/stat : 9375 (aspcud-full) S 9374 9375 1750 0 -1 4202496 739 3606 2 7 0 0 3 2 20 0 1 0 117081053 9433088 365 18446744073709551615 4194304 5129932 140733830911904 140733830910560 140480343413854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9375/statm: 2303 365 303 229 0 63 0
[pid=9391] ppid=9375 vsize=77028 CPUtime=2.76
/proc/9391/stat : 9391 (cudf2lp) R 9375 9375 1750 0 -1 4202496 25054 0 1 0 264 12 0 0 20 0 1 0 117081068 78876672 18991 18446744073709551615 4194304 5690517 140736301849792 140736301846792 4951794 0 0 16781316 0 0 0 0 17 0 0 0 16 0 0
/proc/9391/statm: 19257 18991 174 366 0 18888 0
Current children cumulated CPU time (s) 2.81
Current children cumulated vsize (KiB) 86240

[startup+6.30032 s]
/proc/loadavg: 0.98 0.74 0.35 2/62 9392
/proc/meminfo: memFree=159412/1022884 swapFree=0/0
[pid=9375] ppid=9374 vsize=9212 CPUtime=2.97
/proc/9375/stat : 9375 (aspcud-full) S 9374 9375 1750 0 -1 4202496 765 28662 2 8 1 0 280 16 20 0 1 0 117081053 9433088 365 18446744073709551615 4194304 5129932 140733830911904 140733830910560 140480343413854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9375/statm: 2303 365 303 229 0 63 0
[pid=9392] ppid=9375 vsize=141796 CPUtime=2.99
/proc/9392/stat : 9392 (gringo) R 9375 9375 1750 0 -1 4202496 34602 0 1 0 283 16 0 0 20 0 1 0 117081379 145199104 29420 18446744073709551615 4194304 6531320 140736917130560 140736917126984 5554438 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/9392/statm: 35449 29420 281 571 0 34870 0
Current children cumulated CPU time (s) 5.96
Current children cumulated vsize (KiB) 151008

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

[startup+6.40039 s]
/proc/loadavg: 0.98 0.74 0.35 2/62 9392
/proc/meminfo: memFree=159412/1022884 swapFree=0/0
[pid=9375] ppid=9374 vsize=9212 CPUtime=2.97
/proc/9375/stat : 9375 (aspcud-full) S 9374 9375 1750 0 -1 4202496 765 28662 2 8 1 0 280 16 20 0 1 0 117081053 9433088 365 18446744073709551615 4194304 5129932 140733830911904 140733830910560 140480343413854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9375/statm: 2303 365 303 229 0 63 0
[pid=9392] ppid=9375 vsize=152812 CPUtime=3.09
/proc/9392/stat : 9392 (gringo) R 9375 9375 1750 0 -1 4202496 36971 0 1 0 292 17 0 0 20 0 1 0 117081379 156479488 31789 18446744073709551615 4194304 6531320 140736917130560 140736917126488 5554587 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/9392/statm: 38203 31789 282 571 0 37624 0
Current children cumulated CPU time (s) 6.06
Current children cumulated vsize (KiB) 162024

[startup+8.00031 s]
/proc/loadavg: 0.98 0.74 0.35 2/62 9392
/proc/meminfo: memFree=9864/1022884 swapFree=0/0
[pid=9375] ppid=9374 vsize=9212 CPUtime=2.97
/proc/9375/stat : 9375 (aspcud-full) S 9374 9375 1750 0 -1 4202496 765 28662 2 8 1 0 280 16 20 0 1 0 117081053 9433088 365 18446744073709551615 4194304 5129932 140733830911904 140733830910560 140480343413854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9375/statm: 2303 365 303 229 0 63 0
[pid=9392] ppid=9375 vsize=326332 CPUtime=4.6
/proc/9392/stat : 9392 (gringo) R 9375 9375 1750 0 -1 4202496 75216 0 1 0 429 31 0 0 20 0 1 0 117081379 334163968 65937 18446744073709551615 4194304 6531320 140736917130560 140736917127544 4554880 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/9392/statm: 81583 65937 282 571 0 81004 0
Current children cumulated CPU time (s) 7.57
Current children cumulated vsize (KiB) 335544

[startup+9.60041 s]
/proc/loadavg: 0.98 0.74 0.35 2/63 9394
/proc/meminfo: memFree=240376/1022884 swapFree=0/0
[pid=9375] ppid=9374 vsize=9212 CPUtime=8.16
/proc/9375/stat : 9375 (aspcud-full) S 9374 9375 1750 0 -1 4202496 807 105876 2 9 1 0 756 59 20 0 1 0 117081053 9433088 365 18446744073709551615 4194304 5129932 140733830911904 140733830909968 140480343413854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9375/statm: 2303 365 303 229 0 63 0
[pid=9393] ppid=9375 vsize=92016 CPUtime=0.97
/proc/9393/stat : 9393 (clasp) R 9375 9375 1750 0 -1 4202496 26646 0 0 0 88 9 0 0 20 0 1 0 117081912 94224384 22532 18446744073709551615 4194304 6238623 140736729115152 140736729112848 4356161 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9393/statm: 23004 22532 262 500 0 22501 0
[pid=9394] ppid=9375 vsize=22040 CPUtime=0.02
/proc/9394/stat : 9394 (parse.py) S 9375 9375 1750 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 117081912 22568960 1128 18446744073709551615 4194304 6642060 140735494725200 140735494723560 140081104213792 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9394/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 9.15
Current children cumulated vsize (KiB) 123268

[startup+10.0047 s]
/proc/loadavg: 0.98 0.74 0.35 2/63 9394
/proc/meminfo: memFree=188172/1022884 swapFree=0/0
[pid=9375] ppid=9374 vsize=9212 CPUtime=8.16
/proc/9375/stat : 9375 (aspcud-full) S 9374 9375 1750 0 -1 4202496 807 105876 2 9 1 0 756 59 20 0 1 0 117081053 9433088 365 18446744073709551615 4194304 5129932 140733830911904 140733830909968 140480343413854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9375/statm: 2303 365 303 229 0 63 0
[pid=9393] ppid=9375 vsize=92016 CPUtime=1.37
/proc/9393/stat : 9393 (clasp) R 9375 9375 1750 0 -1 4202496 26648 0 0 0 128 9 0 0 20 0 1 0 117081912 94224384 22534 18446744073709551615 4194304 6238623 140736729115152 140736729112176 4409871 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9393/statm: 23004 22534 264 500 0 22501 0
[pid=9394] ppid=9375 vsize=22040 CPUtime=0.02
/proc/9394/stat : 9394 (parse.py) S 9375 9375 1750 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 117081912 22568960 1128 18446744073709551615 4194304 6642060 140735494725200 140735494723560 140081104213792 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9394/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 9.55
Current children cumulated vsize (KiB) 123268

[startup+10.2004 s]
/proc/loadavg: 0.98 0.74 0.35 2/63 9394
/proc/meminfo: memFree=188172/1022884 swapFree=0/0
[pid=9375] ppid=9374 vsize=9212 CPUtime=8.16
/proc/9375/stat : 9375 (aspcud-full) S 9374 9375 1750 0 -1 4202496 807 105876 2 9 1 0 756 59 20 0 1 0 117081053 9433088 365 18446744073709551615 4194304 5129932 140733830911904 140733830909968 140480343413854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9375/statm: 2303 365 303 229 0 63 0
[pid=9393] ppid=9375 vsize=92016 CPUtime=1.56
/proc/9393/stat : 9393 (clasp) R 9375 9375 1750 0 -1 4202496 26648 0 0 0 147 9 0 0 20 0 1 0 117081912 94224384 22534 18446744073709551615 4194304 6238623 140736729115152 140736729112176 4677225 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9393/statm: 23004 22534 264 500 0 22501 0
[pid=9394] ppid=9375 vsize=22040 CPUtime=0.02
/proc/9394/stat : 9394 (parse.py) S 9375 9375 1750 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 117081912 22568960 1128 18446744073709551615 4194304 6642060 140735494725200 140735494723560 140081104213792 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9394/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 9.74
Current children cumulated vsize (KiB) 123268

[startup+10.3004 s]
/proc/loadavg: 0.98 0.74 0.35 2/63 9394
/proc/meminfo: memFree=188172/1022884 swapFree=0/0
[pid=9375] ppid=9374 vsize=9212 CPUtime=8.16
/proc/9375/stat : 9375 (aspcud-full) S 9374 9375 1750 0 -1 4202496 807 105876 2 9 1 0 756 59 20 0 1 0 117081053 9433088 365 18446744073709551615 4194304 5129932 140733830911904 140733830909968 140480343413854 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/9375/statm: 2303 365 303 229 0 63 0
[pid=9393] ppid=9375 vsize=92016 CPUtime=1.66
/proc/9393/stat : 9393 (clasp) R 9375 9375 1750 0 -1 4202496 26648 0 0 0 157 9 0 0 20 0 1 0 117081912 94224384 22534 18446744073709551615 4194304 6238623 140736729115152 140736729112176 4677160 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9393/statm: 23004 22534 264 500 0 22501 0
[pid=9394] ppid=9375 vsize=22040 CPUtime=0.02
/proc/9394/stat : 9394 (parse.py) S 9375 9375 1750 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 117081912 22568960 1128 18446744073709551615 4194304 6642060 140735494725200 140735494723560 140081104213792 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9394/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 9.84
Current children cumulated vsize (KiB) 123268

Child status: 0
Real time (s): 10.3795
CPU time (s): 9.93662
CPU user time (s): 9.19257
CPU system time (s): 0.744046
CPU usage (%): 95.7334
Max. virtual memory (cumulated for all children) (KiB): 344384

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 9.19257
system time used= 0.744046
maximum resident set size= 271724
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 134957
page faults= 11
swaps= 0
block input operations= 43152
block output operations= 37248
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 95
involuntary context switches= 1200

runsolver used 0.024001 second user time and 0.052003 second system time

The end