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/difficult/rand172.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand172.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/upgrade/upgrade/difficult/rand172.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.04 0.90 0.49 2/65 9055
/proc/meminfo: memFree=549576/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=3152 CPUtime=0
/proc/9055/stat : 9055 (runsolver) R 9054 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 117099804 3227648 32 18446744073709551615 134512640 134586868 4292324864 4292322912 4152169520 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/9055/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.193066 s]
/proc/loadavg: 1.04 0.90 0.49 2/65 9055
/proc/meminfo: memFree=549576/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=9212 CPUtime=0.02
/proc/9055/stat : 9055 (aspcud-full) S 9054 9055 1745 0 -1 4202496 738 3625 0 0 0 0 2 0 20 0 1 0 117099804 9433088 365 18446744073709551615 4194304 5129932 140733544368944 140733544367600 140256159581278 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9055/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200312 s]
/proc/loadavg: 1.04 0.90 0.49 2/65 9055
/proc/meminfo: memFree=549576/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=9212 CPUtime=0.02
/proc/9055/stat : 9055 (aspcud-full) S 9054 9055 1745 0 -1 4202496 738 3625 0 0 0 0 2 0 20 0 1 0 117099804 9433088 365 18446744073709551615 4194304 5129932 140733544368944 140733544367600 140256159581278 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9055/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300291 s]
/proc/loadavg: 1.04 0.90 0.49 2/65 9055
/proc/meminfo: memFree=549576/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=9212 CPUtime=0.02
/proc/9055/stat : 9055 (aspcud-full) S 9054 9055 1745 0 -1 4202496 738 3625 0 0 0 0 2 0 20 0 1 0 117099804 9433088 365 18446744073709551615 4194304 5129932 140733544368944 140733544367600 140256159581278 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9055/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.04 0.90 0.49 2/65 9055
/proc/meminfo: memFree=549576/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=9212 CPUtime=0.02
/proc/9055/stat : 9055 (aspcud-full) S 9054 9055 1745 0 -1 4202496 738 3625 0 0 0 0 2 0 20 0 1 0 117099804 9433088 365 18446744073709551615 4194304 5129932 140733544368944 140733544367600 140256159581278 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9055/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 1.04 0.90 0.49 2/67 9071
/proc/meminfo: memFree=513840/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=9212 CPUtime=0.02
/proc/9055/stat : 9055 (aspcud-full) S 9054 9055 1745 0 -1 4202496 738 3625 0 0 0 0 2 0 20 0 1 0 117099804 9433088 365 18446744073709551615 4194304 5129932 140733544368944 140733544367600 140256159581278 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9055/statm: 2303 365 303 229 0 63 0
[pid=9071] ppid=9055 vsize=34564 CPUtime=1.43
/proc/9071/stat : 9071 (cudf2lp) R 9055 9055 1745 0 -1 4202496 10091 0 0 0 138 5 0 0 20 0 1 0 117099806 35393536 8358 18446744073709551615 4194304 5690517 140734268756000 140734268753640 4360785 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/9071/statm: 8641 8358 160 366 0 8272 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 43776

[startup+3.10033 s]
/proc/loadavg: 1.04 0.90 0.49 2/67 9071
/proc/meminfo: memFree=480732/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=9212 CPUtime=0.02
/proc/9055/stat : 9055 (aspcud-full) S 9054 9055 1745 0 -1 4202496 738 3625 0 0 0 0 2 0 20 0 1 0 117099804 9433088 365 18446744073709551615 4194304 5129932 140733544368944 140733544367600 140256159581278 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9055/statm: 2303 365 303 229 0 63 0
[pid=9071] ppid=9055 vsize=99148 CPUtime=3.01
/proc/9071/stat : 9071 (cudf2lp) R 9055 9055 1745 0 -1 4202496 27991 0 0 0 285 16 0 0 20 0 1 0 117099806 101527552 21264 18446744073709551615 4194304 5690517 140734268756000 140734268753640 4680825 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/9071/statm: 24787 21264 160 366 0 24418 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 108360

[startup+6.30033 s]
/proc/loadavg: 1.04 0.90 0.49 2/67 9072
/proc/meminfo: memFree=495860/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=9212 CPUtime=5.3
/proc/9055/stat : 9055 (aspcud-full) S 9054 9055 1745 0 -1 4202496 762 44903 0 0 0 0 496 34 20 0 1 0 117099804 9433088 365 18446744073709551615 4194304 5129932 140733544368944 140733544367600 140256159581278 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9055/statm: 2303 365 303 229 0 63 0
[pid=9072] ppid=9055 vsize=28744 CPUtime=0.91
/proc/9072/stat : 9072 (gringo) R 9055 9055 1745 0 -1 4202496 7943 0 0 0 85 6 0 0 20 0 1 0 117100341 29433856 5835 18446744073709551615 4194304 6531320 140735758196464 140735758193080 5115580 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/9072/statm: 7186 5835 259 571 0 6607 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 37956

[startup+12.7003 s]
/proc/loadavg: 1.03 0.90 0.49 2/67 9072
/proc/meminfo: memFree=146056/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=9212 CPUtime=5.3
/proc/9055/stat : 9055 (aspcud-full) S 9054 9055 1745 0 -1 4202496 762 44903 0 0 0 0 496 34 20 0 1 0 117099804 9433088 365 18446744073709551615 4194304 5129932 140733544368944 140733544367600 140256159581278 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9055/statm: 2303 365 303 229 0 63 0
[pid=9072] ppid=9055 vsize=489736 CPUtime=7.24
/proc/9072/stat : 9072 (gringo) R 9055 9055 1745 0 -1 4202496 116177 0 0 0 678 46 0 0 20 0 1 0 117100341 501489664 97680 18446744073709551615 4194304 6531320 140735758196464 140735758193080 5521035 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/9072/statm: 122434 97680 282 571 0 121855 0
Current children cumulated CPU time (s) 12.54
Current children cumulated vsize (KiB) 498948

[startup+25.5005 s]
/proc/loadavg: 1.02 0.91 0.50 2/68 9074
/proc/meminfo: memFree=322252/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=9212 CPUtime=14.62
/proc/9055/stat : 9055 (aspcud-full) S 9054 9055 1745 0 -1 4202496 799 180221 0 0 0 0 1357 105 20 0 1 0 117099804 9433088 365 18446744073709551615 4194304 5129932 140733544368944 140733544367008 140256159581278 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9055/statm: 2303 365 303 229 0 63 0
[pid=9073] ppid=9055 vsize=161296 CPUtime=10.56
/proc/9073/stat : 9073 (clasp) R 9055 9055 1745 0 -1 4202496 47982 0 0 0 1038 18 0 0 20 0 1 0 117101283 165167104 39485 18446744073709551615 4194304 6238623 140733484327008 140733484324032 4635573 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9073/statm: 40324 39485 264 500 0 39821 0
[pid=9074] ppid=9055 vsize=22040 CPUtime=0.02
/proc/9074/stat : 9074 (parse.py) S 9055 9055 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 117101283 22568960 1128 18446744073709551615 4194304 6642060 140733446094240 140733446092600 139732732221216 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9074/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.2
Current children cumulated vsize (KiB) 192548

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

[startup+25.6006 s]
/proc/loadavg: 1.02 0.91 0.50 2/68 9074
/proc/meminfo: memFree=322252/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=9212 CPUtime=14.62
/proc/9055/stat : 9055 (aspcud-full) S 9054 9055 1745 0 -1 4202496 799 180221 0 0 0 0 1357 105 20 0 1 0 117099804 9433088 365 18446744073709551615 4194304 5129932 140733544368944 140733544367008 140256159581278 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9055/statm: 2303 365 303 229 0 63 0
[pid=9073] ppid=9055 vsize=161296 CPUtime=10.66
/proc/9073/stat : 9073 (clasp) R 9055 9055 1745 0 -1 4202496 47982 0 0 0 1048 18 0 0 20 0 1 0 117101283 165167104 39485 18446744073709551615 4194304 6238623 140733484327008 140733484324032 4635678 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9073/statm: 40324 39485 264 500 0 39821 0
[pid=9074] ppid=9055 vsize=22040 CPUtime=0.02
/proc/9074/stat : 9074 (parse.py) S 9055 9055 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 117101283 22568960 1128 18446744073709551615 4194304 6642060 140733446094240 140733446092600 139732732221216 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9074/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.3
Current children cumulated vsize (KiB) 192548

[startup+28.8004 s]
/proc/loadavg: 1.02 0.91 0.50 2/68 9074
/proc/meminfo: memFree=322252/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=9212 CPUtime=14.62
/proc/9055/stat : 9055 (aspcud-full) S 9054 9055 1745 0 -1 4202496 799 180221 0 0 0 0 1357 105 20 0 1 0 117099804 9433088 365 18446744073709551615 4194304 5129932 140733544368944 140733544367008 140256159581278 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9055/statm: 2303 365 303 229 0 63 0
[pid=9073] ppid=9055 vsize=161296 CPUtime=13.83
/proc/9073/stat : 9073 (clasp) R 9055 9055 1745 0 -1 4202496 47982 0 0 0 1365 18 0 0 20 0 1 0 117101283 165167104 39485 18446744073709551615 4194304 6238623 140733484327008 140733484324032 4677251 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9073/statm: 40324 39485 264 500 0 39821 0
[pid=9074] ppid=9055 vsize=22040 CPUtime=0.02
/proc/9074/stat : 9074 (parse.py) S 9055 9055 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 117101283 22568960 1128 18446744073709551615 4194304 6642060 140733446094240 140733446092600 139732732221216 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9074/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 28.47
Current children cumulated vsize (KiB) 192548

[startup+30.4003 s]
/proc/loadavg: 1.02 0.91 0.50 2/68 9074
/proc/meminfo: memFree=322252/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=9212 CPUtime=14.62
/proc/9055/stat : 9055 (aspcud-full) S 9054 9055 1745 0 -1 4202496 799 180221 0 0 0 0 1357 105 20 0 1 0 117099804 9433088 365 18446744073709551615 4194304 5129932 140733544368944 140733544367008 140256159581278 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9055/statm: 2303 365 303 229 0 63 0
[pid=9073] ppid=9055 vsize=161296 CPUtime=15.42
/proc/9073/stat : 9073 (clasp) R 9055 9055 1745 0 -1 4202496 47982 0 0 0 1524 18 0 0 20 0 1 0 117101283 165167104 39485 18446744073709551615 4194304 6238623 140733484327008 140733484324032 4676760 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9073/statm: 40324 39485 264 500 0 39821 0
[pid=9074] ppid=9055 vsize=22040 CPUtime=0.02
/proc/9074/stat : 9074 (parse.py) S 9055 9055 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 117101283 22568960 1128 18446744073709551615 4194304 6642060 140733446094240 140733446092600 139732732221216 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9074/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 30.06
Current children cumulated vsize (KiB) 192548

[startup+32.0036 s]
/proc/loadavg: 1.02 0.91 0.50 2/68 9074
/proc/meminfo: memFree=322252/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=9212 CPUtime=14.62
/proc/9055/stat : 9055 (aspcud-full) S 9054 9055 1745 0 -1 4202496 799 180221 0 0 0 0 1357 105 20 0 1 0 117099804 9433088 365 18446744073709551615 4194304 5129932 140733544368944 140733544367008 140256159581278 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9055/statm: 2303 365 303 229 0 63 0
[pid=9073] ppid=9055 vsize=161296 CPUtime=17
/proc/9073/stat : 9073 (clasp) R 9055 9055 1745 0 -1 4202496 47982 0 0 0 1682 18 0 0 20 0 1 0 117101283 165167104 39485 18446744073709551615 4194304 6238623 140733484327008 140733484324032 4635199 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9073/statm: 40324 39485 264 500 0 39821 0
[pid=9074] ppid=9055 vsize=22040 CPUtime=0.02
/proc/9074/stat : 9074 (parse.py) S 9055 9055 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 117101283 22568960 1128 18446744073709551615 4194304 6642060 140733446094240 140733446092600 139732732221216 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9074/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 31.64
Current children cumulated vsize (KiB) 192548

[startup+32.8003 s]
/proc/loadavg: 1.02 0.91 0.50 2/68 9074
/proc/meminfo: memFree=322252/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=9212 CPUtime=14.62
/proc/9055/stat : 9055 (aspcud-full) S 9054 9055 1745 0 -1 4202496 799 180221 0 0 0 0 1357 105 20 0 1 0 117099804 9433088 365 18446744073709551615 4194304 5129932 140733544368944 140733544367008 140256159581278 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9055/statm: 2303 365 303 229 0 63 0
[pid=9073] ppid=9055 vsize=161296 CPUtime=17.8
/proc/9073/stat : 9073 (clasp) R 9055 9055 1745 0 -1 4202496 47982 0 0 0 1762 18 0 0 20 0 1 0 117101283 165167104 39485 18446744073709551615 4194304 6238623 140733484327008 140733484324032 4331850 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9073/statm: 40324 39485 264 500 0 39821 0
[pid=9074] ppid=9055 vsize=22040 CPUtime=0.02
/proc/9074/stat : 9074 (parse.py) S 9055 9055 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 117101283 22568960 1128 18446744073709551615 4194304 6642060 140733446094240 140733446092600 139732732221216 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9074/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 32.44
Current children cumulated vsize (KiB) 192548

[startup+33.2003 s]
/proc/loadavg: 1.02 0.91 0.50 2/68 9074
/proc/meminfo: memFree=322252/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=9212 CPUtime=14.62
/proc/9055/stat : 9055 (aspcud-full) S 9054 9055 1745 0 -1 4202496 799 180221 0 0 0 0 1357 105 20 0 1 0 117099804 9433088 365 18446744073709551615 4194304 5129932 140733544368944 140733544367008 140256159581278 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9055/statm: 2303 365 303 229 0 63 0
[pid=9073] ppid=9055 vsize=161296 CPUtime=18.19
/proc/9073/stat : 9073 (clasp) R 9055 9055 1745 0 -1 4202496 47982 0 0 0 1801 18 0 0 20 0 1 0 117101283 165167104 39485 18446744073709551615 4194304 6238623 140733484327008 140733484324032 4687707 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9073/statm: 40324 39485 264 500 0 39821 0
[pid=9074] ppid=9055 vsize=22040 CPUtime=0.02
/proc/9074/stat : 9074 (parse.py) S 9055 9055 1745 0 -1 4202496 1319 0 0 0 1 1 0 0 20 0 1 0 117101283 22568960 1128 18446744073709551615 4194304 6642060 140733446094240 140733446092600 139732732221216 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9074/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 32.83
Current children cumulated vsize (KiB) 192548

[startup+33.3006 s]
/proc/loadavg: 1.02 0.91 0.50 2/68 9074
/proc/meminfo: memFree=322252/1022884 swapFree=0/0
[pid=9055] ppid=9054 vsize=9212 CPUtime=32.94
/proc/9055/stat : 9055 (aspcud-full) S 9054 9055 1745 0 -1 4202496 836 229558 0 0 0 0 3165 129 20 0 1 0 117099804 9433088 365 18446744073709551615 4194304 5129932 140733544368944 140733544366496 140256159581278 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9055/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 32.94
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 33.3091
CPU time (s): 32.9661
CPU user time (s): 31.658
CPU system time (s): 1.30808
CPU usage (%): 98.9701
Max. virtual memory (cumulated for all children) (KiB): 586496

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 31.658
system time used= 1.30808
maximum resident set size= 467268
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 230631
page faults= 0
swaps= 0
block input operations= 68424
block output operations= 65200
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 70
involuntary context switches= 3805

runsolver used 0.084005 second user time and 0.156009 second system time

The end