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/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/upgrade/upgrade/difficult/rand289.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

[startup+0 s]
/proc/loadavg: 1.05 1.04 0.75 2/57 15681
/proc/meminfo: memFree=525332/1022884 swapFree=0/0
[pid=15681] ppid=15680 vsize=3152 CPUtime=0
/proc/15681/stat : 15681 (runsolver) R 15680 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 38931783 3227648 33 18446744073709551615 134512640 134586868 4293358768 4293356816 4151370800 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/15681/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.177788 s]
/proc/loadavg: 1.05 1.04 0.75 2/57 15681
/proc/meminfo: memFree=525332/1022884 swapFree=0/0
[pid=15681] ppid=15680 vsize=9212 CPUtime=0.02
/proc/15681/stat : 15681 (aspuncud-full) S 15680 15681 32685 0 -1 4202496 695 2808 0 2 0 0 1 1 20 0 1 0 38931783 9433088 365 18446744073709551615 4194304 5129932 140734099042432 140734099041088 140439191168094 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15681/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200328 s]
/proc/loadavg: 1.05 1.04 0.75 2/57 15681
/proc/meminfo: memFree=525332/1022884 swapFree=0/0
[pid=15681] ppid=15680 vsize=9212 CPUtime=0.02
/proc/15681/stat : 15681 (aspuncud-full) S 15680 15681 32685 0 -1 4202496 695 2808 0 2 0 0 1 1 20 0 1 0 38931783 9433088 365 18446744073709551615 4194304 5129932 140734099042432 140734099041088 140439191168094 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15681/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300311 s]
/proc/loadavg: 1.05 1.04 0.75 2/57 15681
/proc/meminfo: memFree=525332/1022884 swapFree=0/0
[pid=15681] ppid=15680 vsize=9212 CPUtime=0.02
/proc/15681/stat : 15681 (aspuncud-full) S 15680 15681 32685 0 -1 4202496 695 2808 0 2 0 0 1 1 20 0 1 0 38931783 9433088 365 18446744073709551615 4194304 5129932 140734099042432 140734099041088 140439191168094 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15681/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700239 s]
/proc/loadavg: 1.05 1.04 0.75 2/57 15681
/proc/meminfo: memFree=525332/1022884 swapFree=0/0
[pid=15681] ppid=15680 vsize=9212 CPUtime=0.02
/proc/15681/stat : 15681 (aspuncud-full) S 15680 15681 32685 0 -1 4202496 695 2808 0 2 0 0 1 1 20 0 1 0 38931783 9433088 365 18446744073709551615 4194304 5129932 140734099042432 140734099041088 140439191168094 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15681/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50026 s]
/proc/loadavg: 1.05 1.04 0.75 2/59 15694
/proc/meminfo: memFree=490464/1022884 swapFree=0/0
[pid=15681] ppid=15680 vsize=9212 CPUtime=0.02
/proc/15681/stat : 15681 (aspuncud-full) S 15680 15681 32685 0 -1 4202496 695 2808 0 2 0 0 1 1 20 0 1 0 38931783 9433088 365 18446744073709551615 4194304 5129932 140734099042432 140734099041088 140439191168094 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15681/statm: 2303 365 303 229 0 63 0
[pid=15694] ppid=15681 vsize=53760 CPUtime=1.27
/proc/15694/stat : 15694 (cudf2lp) R 15681 15681 32685 0 -1 4202496 14974 0 0 0 121 6 0 0 20 0 1 0 38931790 55050240 11575 18446744073709551615 4194304 5690517 140736121156704 140736121154344 4293647 0 0 16781316 0 0 0 0 17 0 0 0 14 0 0
/proc/15694/statm: 13440 11575 160 366 0 13071 0
Current children cumulated CPU time (s) 1.29
Current children cumulated vsize (KiB) 62972

[startup+3.10032 s]
/proc/loadavg: 1.05 1.04 0.75 1/59 15694
/proc/meminfo: memFree=452272/1022884 swapFree=0/0
[pid=15681] ppid=15680 vsize=9212 CPUtime=0.02
/proc/15681/stat : 15681 (aspuncud-full) S 15680 15681 32685 0 -1 4202496 695 2808 0 2 0 0 1 1 20 0 1 0 38931783 9433088 365 18446744073709551615 4194304 5129932 140734099042432 140734099041088 140439191168094 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15681/statm: 2303 365 303 229 0 63 0
[pid=15694] ppid=15681 vsize=99148 CPUtime=2.66
/proc/15694/stat : 15694 (cudf2lp) R 15681 15681 32685 0 -1 4202496 28313 0 0 0 254 12 0 0 20 0 1 0 38931790 101527552 21585 18446744073709551615 4194304 5690517 140736121156704 140736121154344 5006665 0 0 16781316 0 0 0 0 17 0 0 0 35 0 0
/proc/15694/statm: 24787 21585 160 366 0 24418 0
Current children cumulated CPU time (s) 2.68
Current children cumulated vsize (KiB) 108360

[startup+6.30027 s]
/proc/loadavg: 1.04 1.04 0.75 2/59 15695
/proc/meminfo: memFree=448800/1022884 swapFree=0/0
[pid=15681] ppid=15680 vsize=9212 CPUtime=4.47
/proc/15681/stat : 15681 (aspuncud-full) S 15680 15681 32685 0 -1 4202496 722 44087 0 2 0 0 418 29 20 0 1 0 38931783 9433088 365 18446744073709551615 4194304 5129932 140734099042432 140734099041088 140439191168094 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15681/statm: 2303 365 303 229 0 63 0
[pid=15695] ppid=15681 vsize=68516 CPUtime=1.39
/proc/15695/stat : 15695 (gringo) R 15681 15681 32685 0 -1 4202496 19380 0 0 0 131 8 0 0 20 0 1 0 38932273 70160384 13173 18446744073709551615 4194304 6531320 140736802335776 140736802332040 4586520 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/15695/statm: 17129 13173 259 571 0 16550 0
Current children cumulated CPU time (s) 5.86
Current children cumulated vsize (KiB) 77728

[startup+12.7003 s]
/proc/loadavg: 1.04 1.03 0.75 2/60 15697
/proc/meminfo: memFree=380308/1022884 swapFree=0/0
[pid=15681] ppid=15680 vsize=9212 CPUtime=11.18
/proc/15681/stat : 15681 (aspuncud-full) S 15680 15681 32685 0 -1 4202496 761 186889 0 2 0 0 1028 90 20 0 1 0 38931783 9433088 365 18446744073709551615 4194304 5129932 140734099042432 140734099040496 140439191168094 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15681/statm: 2303 365 303 229 0 63 0
[pid=15696] ppid=15681 vsize=180532 CPUtime=0.95
/proc/15696/stat : 15696 (unclasp) R 15681 15681 32685 0 -1 4202496 49937 0 0 0 79 16 0 0 20 0 1 0 38932956 184864768 43703 18446744073709551615 4194304 6012874 140735444691584 140735444690344 4519837 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/15696/statm: 45133 43703 206 444 0 44681 0
[pid=15697] ppid=15681 vsize=22040 CPUtime=0.01
/proc/15697/stat : 15697 (parse.py) S 15681 15681 32685 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 38932956 22568960 1129 18446744073709551615 4194304 6642060 140735585738944 140735585737304 140383624587040 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/15697/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 12.14
Current children cumulated vsize (KiB) 211784

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

[startup+12.8005 s]
/proc/loadavg: 1.04 1.03 0.75 2/60 15697
/proc/meminfo: memFree=380308/1022884 swapFree=0/0
[pid=15681] ppid=15680 vsize=9212 CPUtime=11.18
/proc/15681/stat : 15681 (aspuncud-full) S 15680 15681 32685 0 -1 4202496 761 186889 0 2 0 0 1028 90 20 0 1 0 38931783 9433088 365 18446744073709551615 4194304 5129932 140734099042432 140734099040496 140439191168094 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15681/statm: 2303 365 303 229 0 63 0
[pid=15696] ppid=15681 vsize=180532 CPUtime=1.04
/proc/15696/stat : 15696 (unclasp) R 15681 15681 32685 0 -1 4202496 49959 0 0 0 88 16 0 0 20 0 1 0 38932956 184864768 43725 18446744073709551615 4194304 6012874 140735444691584 140735444690904 4548507 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/15696/statm: 45133 43725 220 444 0 44681 0
[pid=15697] ppid=15681 vsize=22040 CPUtime=0.01
/proc/15697/stat : 15697 (parse.py) S 15681 15681 32685 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 38932956 22568960 1129 18446744073709551615 4194304 6642060 140735585738944 140735585737304 140383624587040 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/15697/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 12.23
Current children cumulated vsize (KiB) 211784

[startup+13.2003 s]
/proc/loadavg: 1.04 1.03 0.75 2/60 15697
/proc/meminfo: memFree=485212/1022884 swapFree=0/0
[pid=15681] ppid=15680 vsize=9212 CPUtime=11.18
/proc/15681/stat : 15681 (aspuncud-full) S 15680 15681 32685 0 -1 4202496 761 186889 0 2 0 0 1028 90 20 0 1 0 38931783 9433088 365 18446744073709551615 4194304 5129932 140734099042432 140734099040496 140439191168094 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/15681/statm: 2303 365 303 229 0 63 0
[pid=15696] ppid=15681 vsize=133052 CPUtime=1.44
/proc/15696/stat : 15696 (unclasp) R 15681 15681 32685 0 -1 4202496 49988 0 0 0 124 20 0 0 20 0 1 0 38932956 136245248 4930 18446744073709551615 4194304 6012874 140735444691584 140735444690984 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/15696/statm: 33263 4930 234 444 0 32811 0
[pid=15697] ppid=15681 vsize=22372 CPUtime=0.02
/proc/15697/stat : 15697 (parse.py) S 15681 15681 32685 0 -1 4202496 1391 0 0 0 2 0 0 0 20 0 1 0 38932956 22908928 1200 18446744073709551615 4194304 6642060 140735585738944 140735585737112 140383624587040 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/15697/statm: 5593 1200 508 598 0 679 0
Current children cumulated CPU time (s) 12.64
Current children cumulated vsize (KiB) 164636

Child status: 0
Real time (s): 13.247
CPU time (s): 12.6888
CPU user time (s): 11.5487
CPU system time (s): 1.14007
CPU usage (%): 95.7864
Max. virtual memory (cumulated for all children) (KiB): 618456

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 11.5487
system time used= 1.14007
maximum resident set size= 497204
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 239313
page faults= 2
swaps= 0
block input operations= 68560
block output operations= 68888
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 200
involuntary context switches= 366

runsolver used 0.020001 second user time and 0.052003 second system time

The end