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

[startup+0 s]
/proc/loadavg: 1.00 1.01 1.00 2/59 30861
/proc/meminfo: memFree=525048/1022884 swapFree=0/0
[pid=30861] ppid=30860 vsize=3152 CPUtime=0
/proc/30861/stat : 30861 (runsolver) R 30860 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 118045271 3227648 32 18446744073709551615 134512640 134586868 4287487216 4287485264 4151596080 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/30861/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.162807 s]
/proc/loadavg: 1.00 1.01 1.00 2/59 30861
/proc/meminfo: memFree=525048/1022884 swapFree=0/0
[pid=30861] ppid=30860 vsize=9212 CPUtime=0.02
/proc/30861/stat : 30861 (aspuncud-full) S 30860 30861 1733 0 -1 4202496 694 2810 0 0 0 0 1 1 20 0 1 0 118045271 9433088 365 18446744073709551615 4194304 5129932 140734767304448 140734767303104 140142681810014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30861/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200272 s]
/proc/loadavg: 1.00 1.01 1.00 2/59 30861
/proc/meminfo: memFree=525048/1022884 swapFree=0/0
[pid=30861] ppid=30860 vsize=9212 CPUtime=0.02
/proc/30861/stat : 30861 (aspuncud-full) S 30860 30861 1733 0 -1 4202496 694 2810 0 0 0 0 1 1 20 0 1 0 118045271 9433088 365 18446744073709551615 4194304 5129932 140734767304448 140734767303104 140142681810014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30861/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.30026 s]
/proc/loadavg: 1.00 1.01 1.00 2/59 30861
/proc/meminfo: memFree=525048/1022884 swapFree=0/0
[pid=30861] ppid=30860 vsize=9212 CPUtime=0.02
/proc/30861/stat : 30861 (aspuncud-full) S 30860 30861 1733 0 -1 4202496 694 2810 0 0 0 0 1 1 20 0 1 0 118045271 9433088 365 18446744073709551615 4194304 5129932 140734767304448 140734767303104 140142681810014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30861/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700224 s]
/proc/loadavg: 1.00 1.01 1.00 2/59 30861
/proc/meminfo: memFree=525048/1022884 swapFree=0/0
[pid=30861] ppid=30860 vsize=9212 CPUtime=0.02
/proc/30861/stat : 30861 (aspuncud-full) S 30860 30861 1733 0 -1 4202496 694 2810 0 0 0 0 1 1 20 0 1 0 118045271 9433088 365 18446744073709551615 4194304 5129932 140734767304448 140734767303104 140142681810014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30861/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50043 s]
/proc/loadavg: 1.00 1.01 1.00 2/61 30874
/proc/meminfo: memFree=478772/1022884 swapFree=0/0
[pid=30861] ppid=30860 vsize=9212 CPUtime=0.02
/proc/30861/stat : 30861 (aspuncud-full) S 30860 30861 1733 0 -1 4202496 694 2810 0 0 0 0 1 1 20 0 1 0 118045271 9433088 365 18446744073709551615 4194304 5129932 140734767304448 140734767303104 140142681810014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30861/statm: 2303 365 303 229 0 63 0
[pid=30874] ppid=30861 vsize=53756 CPUtime=1.26
/proc/30874/stat : 30874 (cudf2lp) D 30861 30861 1733 0 -1 4202496 15274 0 0 0 121 5 0 0 20 0 1 0 118045273 55046144 11875 18446744073709551615 4194304 5690517 140735618430992 140735618428680 5058400 0 0 16781316 0 0 0 0 17 0 0 0 13 0 0
/proc/30874/statm: 13439 11875 160 366 0 13070 0
Current children cumulated CPU time (s) 1.28
Current children cumulated vsize (KiB) 62968

[startup+3.10027 s]
/proc/loadavg: 1.00 1.01 1.00 2/61 30874
/proc/meminfo: memFree=451120/1022884 swapFree=0/0
[pid=30861] ppid=30860 vsize=9212 CPUtime=0.02
/proc/30861/stat : 30861 (aspuncud-full) S 30860 30861 1733 0 -1 4202496 694 2810 0 0 0 0 1 1 20 0 1 0 118045271 9433088 365 18446744073709551615 4194304 5129932 140734767304448 140734767303104 140142681810014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30861/statm: 2303 365 303 229 0 63 0
[pid=30874] ppid=30861 vsize=99144 CPUtime=2.62
/proc/30874/stat : 30874 (cudf2lp) R 30861 30861 1733 0 -1 4202496 28426 0 0 0 253 9 0 0 20 0 1 0 118045273 101523456 21698 18446744073709551615 4194304 5690517 140735618430992 140735618428632 4360825 0 0 16781316 0 0 0 0 17 0 0 0 43 0 0
/proc/30874/statm: 24786 21698 160 366 0 24417 0
Current children cumulated CPU time (s) 2.64
Current children cumulated vsize (KiB) 108356

[startup+6.30031 s]
/proc/loadavg: 1.00 1.01 1.00 2/61 30875
/proc/meminfo: memFree=450500/1022884 swapFree=0/0
[pid=30861] ppid=30860 vsize=9212 CPUtime=4.16
/proc/30861/stat : 30861 (aspuncud-full) S 30860 30861 1733 0 -1 4202496 721 44088 0 0 0 0 397 19 20 0 1 0 118045271 9433088 365 18446744073709551615 4194304 5129932 140734767304448 140734767303104 140142681810014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30861/statm: 2303 365 303 229 0 63 0
[pid=30875] ppid=30861 vsize=49872 CPUtime=1.63
/proc/30875/stat : 30875 (gringo) R 30861 30861 1733 0 -1 4202496 14320 0 0 0 157 6 0 0 20 0 1 0 118045735 51068928 10162 18446744073709551615 4194304 6531320 140736131942960 140736131939576 4348373 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/30875/statm: 12468 10162 259 571 0 11889 0
Current children cumulated CPU time (s) 5.79
Current children cumulated vsize (KiB) 59084

[startup+12.7003 s]
/proc/loadavg: 1.00 1.01 1.00 2/61 30875
/proc/meminfo: memFree=9740/1022884 swapFree=0/0
[pid=30861] ppid=30860 vsize=9212 CPUtime=4.16
/proc/30861/stat : 30861 (aspuncud-full) S 30860 30861 1733 0 -1 4202496 721 44088 0 0 0 0 397 19 20 0 1 0 118045271 9433088 365 18446744073709551615 4194304 5129932 140734767304448 140734767303104 140142681810014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30861/statm: 2303 365 303 229 0 63 0
[pid=30875] ppid=30861 vsize=609260 CPUtime=7.9
/proc/30875/stat : 30875 (gringo) R 30861 30861 1733 0 -1 4202496 142810 0 0 0 740 50 0 0 20 0 1 0 118045735 623882240 124313 18446744073709551615 4194304 6531320 140736131942960 140736131939720 5520711 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/30875/statm: 152315 124313 283 571 0 151736 0
Current children cumulated CPU time (s) 12.06
Current children cumulated vsize (KiB) 618472

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

[startup+12.8004 s]
/proc/loadavg: 1.00 1.01 1.00 2/61 30875
/proc/meminfo: memFree=9740/1022884 swapFree=0/0
[pid=30861] ppid=30860 vsize=9212 CPUtime=4.16
/proc/30861/stat : 30861 (aspuncud-full) S 30860 30861 1733 0 -1 4202496 721 44088 0 0 0 0 397 19 20 0 1 0 118045271 9433088 365 18446744073709551615 4194304 5129932 140734767304448 140734767303104 140142681810014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30861/statm: 2303 365 303 229 0 63 0
[pid=30875] ppid=30861 vsize=609260 CPUtime=8
/proc/30875/stat : 30875 (gringo) R 30861 30861 1733 0 -1 4202496 142810 0 0 0 750 50 0 0 20 0 1 0 118045735 623882240 124313 18446744073709551615 4194304 6531320 140736131942960 140736131939720 5502254 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/30875/statm: 152315 124313 283 571 0 151736 0
Current children cumulated CPU time (s) 12.16
Current children cumulated vsize (KiB) 618472

[startup+13.6002 s]
/proc/loadavg: 1.00 1.01 1.00 2/61 30875
/proc/meminfo: memFree=354724/1022884 swapFree=0/0
[pid=30861] ppid=30860 vsize=9212 CPUtime=12.61
/proc/30861/stat : 30861 (aspuncud-full) S 30860 30861 1733 0 -1 4202496 760 186902 0 0 0 0 1179 82 20 0 1 0 118045271 9433088 365 18446744073709551615 4194304 5129932 140734767304448 140734767302512 140142681810014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30861/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 12.61
Current children cumulated vsize (KiB) 9212

[startup+14.4033 s]
/proc/loadavg: 1.00 1.01 1.00 2/62 30877
/proc/meminfo: memFree=329252/1022884 swapFree=0/0
[pid=30861] ppid=30860 vsize=9212 CPUtime=12.61
/proc/30861/stat : 30861 (aspuncud-full) S 30860 30861 1733 0 -1 4202496 760 186902 0 0 0 0 1179 82 20 0 1 0 118045271 9433088 365 18446744073709551615 4194304 5129932 140734767304448 140734767302512 140142681810014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30861/statm: 2303 365 303 229 0 63 0
[pid=30876] ppid=30861 vsize=168120 CPUtime=1.09
/proc/30876/stat : 30876 (unclasp) R 30861 30861 1733 0 -1 4202496 49926 0 1 0 88 21 0 0 20 0 1 0 118046595 172154880 41274 18446744073709551615 4194304 6012874 140737262006832 140737262006152 5260310 0 0 16781316 16386 0 0 0 17 0 0 0 4 0 0
/proc/30876/statm: 42030 41274 219 444 0 41578 0
[pid=30877] ppid=30861 vsize=22040 CPUtime=0
/proc/30877/stat : 30877 (parse.py) S 30861 30861 1733 0 -1 4202496 1306 0 13 0 0 0 0 0 20 0 1 0 118046595 22568960 1128 18446744073709551615 4194304 6642060 140734706328160 140734706326520 140699353425696 0 0 16777220 20994 0 0 0 17 0 0 0 20 0 0
/proc/30877/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 13.7
Current children cumulated vsize (KiB) 199372

[startup+14.6003 s]
/proc/loadavg: 1.00 1.01 1.00 2/62 30877
/proc/meminfo: memFree=329252/1022884 swapFree=0/0
[pid=30861] ppid=30860 vsize=9212 CPUtime=12.61
/proc/30861/stat : 30861 (aspuncud-full) S 30860 30861 1733 0 -1 4202496 760 186902 0 0 0 0 1179 82 20 0 1 0 118045271 9433088 365 18446744073709551615 4194304 5129932 140734767304448 140734767302512 140142681810014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30861/statm: 2303 365 303 229 0 63 0
[pid=30876] ppid=30861 vsize=168120 CPUtime=1.28
/proc/30876/stat : 30876 (unclasp) R 30861 30861 1733 0 -1 4202496 49955 0 1 0 107 21 0 0 20 0 1 0 118046595 172154880 41303 18446744073709551615 4194304 6012874 140737262006832 140737262006376 5256141 0 0 16781316 16386 0 0 0 17 0 0 0 4 0 0
/proc/30876/statm: 42030 41303 233 444 0 41578 0
[pid=30877] ppid=30861 vsize=22372 CPUtime=0.01
/proc/30877/stat : 30877 (parse.py) S 30861 30861 1733 0 -1 4202496 1377 0 13 0 1 0 0 0 20 0 1 0 118046595 22908928 1199 18446744073709551615 4194304 6642060 140734706328160 140734706326360 140699353425696 0 0 16777220 20994 0 0 0 17 0 0 0 20 0 0
/proc/30877/statm: 5593 1199 508 598 0 679 0
Current children cumulated CPU time (s) 13.9
Current children cumulated vsize (KiB) 199704

Child status: 0
Real time (s): 14.6887
CPU time (s): 14.0129
CPU user time (s): 12.9048
CPU system time (s): 1.10807
CPU usage (%): 95.3991
Max. virtual memory (cumulated for all children) (KiB): 618472

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 12.9048
system time used= 1.10807
maximum resident set size= 497252
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 239279
page faults= 15
swaps= 0
block input operations= 70040
block output operations= 68856
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 203
involuntary context switches= 1771

runsolver used 0.048003 second user time and 0.040002 second system time

The end