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/upgrade/easy/rand377.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand377.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/dist-upgrade/upgrade/easy/rand377.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: 0.98 1.01 1.01 2/60 17955
/proc/meminfo: memFree=522740/1022884 swapFree=0/0
[pid=17955] ppid=17954 vsize=3152 CPUtime=0
/proc/17955/stat : 17955 (runsolver) R 17954 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 39743390 3227648 32 18446744073709551615 134512640 134586868 4291576320 4291574368 4152144944 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/17955/statm: 788 32 0 19 0 73 0

[startup+0.17559 s]
/proc/loadavg: 0.98 1.01 1.01 2/60 17955
/proc/meminfo: memFree=522740/1022884 swapFree=0/0
[pid=17955] ppid=17954 vsize=9212 CPUtime=0.04
/proc/17955/stat : 17955 (aspcud-full) S 17954 17955 32685 0 -1 4202496 739 3608 2 7 0 0 3 1 20 0 1 0 39743390 9433088 365 18446744073709551615 4194304 5129932 140734760501936 140734760500592 140373521618014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17955/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.20038 s]
/proc/loadavg: 0.98 1.01 1.01 2/60 17955
/proc/meminfo: memFree=522740/1022884 swapFree=0/0
[pid=17955] ppid=17954 vsize=9212 CPUtime=0.04
/proc/17955/stat : 17955 (aspcud-full) S 17954 17955 32685 0 -1 4202496 739 3608 2 7 0 0 3 1 20 0 1 0 39743390 9433088 365 18446744073709551615 4194304 5129932 140734760501936 140734760500592 140373521618014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17955/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.30031 s]
/proc/loadavg: 0.98 1.01 1.01 2/60 17955
/proc/meminfo: memFree=522740/1022884 swapFree=0/0
[pid=17955] ppid=17954 vsize=9212 CPUtime=0.04
/proc/17955/stat : 17955 (aspcud-full) S 17954 17955 32685 0 -1 4202496 739 3608 2 7 0 0 3 1 20 0 1 0 39743390 9433088 365 18446744073709551615 4194304 5129932 140734760501936 140734760500592 140373521618014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17955/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700234 s]
/proc/loadavg: 0.98 1.01 1.01 2/60 17955
/proc/meminfo: memFree=522740/1022884 swapFree=0/0
[pid=17955] ppid=17954 vsize=9212 CPUtime=0.04
/proc/17955/stat : 17955 (aspcud-full) S 17954 17955 32685 0 -1 4202496 739 3608 2 7 0 0 3 1 20 0 1 0 39743390 9433088 365 18446744073709551615 4194304 5129932 140734760501936 140734760500592 140373521618014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17955/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: 0.98 1.01 1.01 2/62 17971
/proc/meminfo: memFree=488988/1022884 swapFree=0/0
[pid=17955] ppid=17954 vsize=9212 CPUtime=0.04
/proc/17955/stat : 17955 (aspcud-full) S 17954 17955 32685 0 -1 4202496 739 3608 2 7 0 0 3 1 20 0 1 0 39743390 9433088 365 18446744073709551615 4194304 5129932 140734760501936 140734760500592 140373521618014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17955/statm: 2303 365 303 229 0 63 0
[pid=17971] ppid=17955 vsize=30832 CPUtime=1.28
/proc/17971/stat : 17971 (cudf2lp) R 17955 17955 32685 0 -1 4202496 9115 0 0 0 123 5 0 0 20 0 1 0 39743407 31571968 7382 18446744073709551615 4194304 5690517 140735856618336 140735856615976 4360304 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/17971/statm: 7708 7382 159 366 0 7339 0
Current children cumulated CPU time (s) 1.32
Current children cumulated vsize (KiB) 40044

[startup+3.10031 s]
/proc/loadavg: 0.98 1.01 1.01 2/62 17971
/proc/meminfo: memFree=456500/1022884 swapFree=0/0
[pid=17955] ppid=17954 vsize=9212 CPUtime=0.04
/proc/17955/stat : 17955 (aspcud-full) S 17954 17955 32685 0 -1 4202496 739 3608 2 7 0 0 3 1 20 0 1 0 39743390 9433088 365 18446744073709551615 4194304 5129932 140734760501936 140734760500592 140373521618014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17955/statm: 2303 365 303 229 0 63 0
[pid=17971] ppid=17955 vsize=77028 CPUtime=2.86
/proc/17971/stat : 17971 (cudf2lp) R 17955 17955 32685 0 -1 4202496 25054 0 0 0 272 14 0 0 20 0 1 0 39743407 78876672 18991 18446744073709551615 4194304 5690517 140735856618336 140735856615656 4957065 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/17971/statm: 19257 18991 174 366 0 18888 0
Current children cumulated CPU time (s) 2.9
Current children cumulated vsize (KiB) 86240

[startup+6.30026 s]
/proc/loadavg: 0.98 1.01 1.01 2/62 17972
/proc/meminfo: memFree=407644/1022884 swapFree=0/0
[pid=17955] ppid=17954 vsize=9212 CPUtime=3.14
/proc/17955/stat : 17955 (aspcud-full) S 17954 17955 32685 0 -1 4202496 766 28664 2 7 0 0 294 20 20 0 1 0 39743390 9433088 365 18446744073709551615 4194304 5129932 140734760501936 140734760500592 140373521618014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17955/statm: 2303 365 303 229 0 63 0
[pid=17972] ppid=17955 vsize=187032 CPUtime=2.92
/proc/17972/stat : 17972 (gringo) R 17955 17955 32685 0 -1 4202496 46314 0 1 0 267 25 0 0 20 0 1 0 39743723 191520768 41133 18446744073709551615 4194304 6531320 140734795403392 140734795399816 4452684 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/17972/statm: 46758 41133 282 571 0 46179 0
Current children cumulated CPU time (s) 6.06
Current children cumulated vsize (KiB) 196244

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

[startup+6.40033 s]
/proc/loadavg: 0.98 1.01 1.01 2/62 17972
/proc/meminfo: memFree=407644/1022884 swapFree=0/0
[pid=17955] ppid=17954 vsize=9212 CPUtime=3.14
/proc/17955/stat : 17955 (aspcud-full) S 17954 17955 32685 0 -1 4202496 766 28664 2 7 0 0 294 20 20 0 1 0 39743390 9433088 365 18446744073709551615 4194304 5129932 140734760501936 140734760500592 140373521618014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17955/statm: 2303 365 303 229 0 63 0
[pid=17972] ppid=17955 vsize=203020 CPUtime=3.02
/proc/17972/stat : 17972 (gringo) R 17955 17955 32685 0 -1 4202496 49730 0 1 0 276 26 0 0 20 0 1 0 39743723 207892480 44549 18446744073709551615 4194304 6531320 140734795403392 140734795400008 4592907 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/17972/statm: 50755 44549 282 571 0 50176 0
Current children cumulated CPU time (s) 6.16
Current children cumulated vsize (KiB) 212232

[startup+7.20028 s]
/proc/loadavg: 0.98 1.01 1.01 2/62 17972
/proc/meminfo: memFree=281412/1022884 swapFree=0/0
[pid=17955] ppid=17954 vsize=9212 CPUtime=3.14
/proc/17955/stat : 17955 (aspcud-full) S 17954 17955 32685 0 -1 4202496 766 28664 2 7 0 0 294 20 20 0 1 0 39743390 9433088 365 18446744073709551615 4194304 5129932 140734760501936 140734760500592 140373521618014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17955/statm: 2303 365 303 229 0 63 0
[pid=17972] ppid=17955 vsize=302360 CPUtime=3.82
/proc/17972/stat : 17972 (gringo) R 17955 17955 32685 0 -1 4202496 73160 0 1 0 350 32 0 0 20 0 1 0 39743723 309616640 63209 18446744073709551615 4194304 6531320 140734795403392 140734795401064 4344262 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/17972/statm: 75590 63209 283 571 0 75011 0
Current children cumulated CPU time (s) 6.96
Current children cumulated vsize (KiB) 311572

[startup+8.00032 s]
/proc/loadavg: 0.98 1.01 1.01 2/63 17974
/proc/meminfo: memFree=395980/1022884 swapFree=0/0
[pid=17955] ppid=17954 vsize=9212 CPUtime=7.11
/proc/17955/stat : 17955 (aspcud-full) S 17954 17955 32685 0 -1 4202496 807 101828 2 8 0 0 653 58 20 0 1 0 39743390 9433088 365 18446744073709551615 4194304 5129932 140734760501936 140734760500000 140373521618014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17955/statm: 2303 365 303 229 0 63 0
[pid=17973] ppid=17955 vsize=86032 CPUtime=0.62
/proc/17973/stat : 17973 (clasp) R 17955 17955 32685 0 -1 4202496 25059 0 0 0 55 7 0 0 20 0 1 0 39744125 88096768 21029 18446744073709551615 4194304 6238623 140733719594304 140733719591328 4635076 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/17973/statm: 21508 21029 263 500 0 21005 0
[pid=17974] ppid=17955 vsize=22040 CPUtime=0.01
/proc/17974/stat : 17974 (parse.py) S 17955 17955 32685 0 -1 4202496 1317 0 0 0 1 0 0 0 20 0 1 0 39744125 22568960 1127 18446744073709551615 4194304 6642060 140736462899312 140736462897672 140299123984160 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17974/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 7.74
Current children cumulated vsize (KiB) 117284

[startup+8.40075 s]
/proc/loadavg: 0.98 1.01 1.01 2/63 17974
/proc/meminfo: memFree=395980/1022884 swapFree=0/0
[pid=17955] ppid=17954 vsize=9212 CPUtime=7.11
/proc/17955/stat : 17955 (aspcud-full) S 17954 17955 32685 0 -1 4202496 807 101828 2 8 0 0 653 58 20 0 1 0 39743390 9433088 365 18446744073709551615 4194304 5129932 140734760501936 140734760500000 140373521618014 0 65536 16781316 1115778811 0 0 0 17 0 0 0 3 0 0
/proc/17955/statm: 2303 365 303 229 0 63 0
[pid=17973] ppid=17955 vsize=86032 CPUtime=1.02
/proc/17973/stat : 17973 (clasp) R 17955 17955 32685 0 -1 4202496 25070 0 0 0 94 8 0 0 20 0 1 0 39744125 88096768 10800 18446744073709551615 4194304 6238623 140733719594304 140733719593832 5666714 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/17973/statm: 21508 10800 274 500 0 21005 0
[pid=17974] ppid=17955 vsize=22044 CPUtime=0.01
/proc/17974/stat : 17974 (parse.py) S 17955 17955 32685 0 -1 4202496 1319 0 0 0 1 0 0 0 20 0 1 0 39744125 22573056 1129 18446744073709551615 4194304 6642060 140736462899312 140736462897592 140299123984160 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/17974/statm: 5511 1129 508 598 0 597 0
Current children cumulated CPU time (s) 8.14
Current children cumulated vsize (KiB) 117288

Child status: 0
Real time (s): 8.42159
CPU time (s): 8.20051
CPU user time (s): 7.50047
CPU system time (s): 0.700043
CPU usage (%): 97.3749
Max. virtual memory (cumulated for all children) (KiB): 315672

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.50047
system time used= 0.700043
maximum resident set size= 255528
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 129319
page faults= 10
swaps= 0
block input operations= 43024
block output operations= 35440
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 88
involuntary context switches= 159

runsolver used 0.008 second user time and 0.052003 second system time

The end