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/trendy-size/install/rand411.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand411.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/install/rand411.cudf.result -count(removed),-sum(solution,installedsize),-notuptodate(solution),-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.88 0.99 1.02 2/59 32498
/proc/meminfo: memFree=708472/1022884 swapFree=0/0
[pid=32498] ppid=32497 vsize=9204 CPUtime=0
/proc/32498/stat : 32498 (aspcud-full) S 32497 32498 1733 0 -1 4202496 431 0 0 0 0 0 0 0 20 0 1 0 118832478 9424896 332 18446744073709551615 4194304 5129932 140733307233088 140733307230552 140429248640800 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/32498/statm: 2301 332 272 229 0 61 0

[startup+0.184934 s]
/proc/loadavg: 0.88 0.99 1.02 2/59 32498
/proc/meminfo: memFree=708472/1022884 swapFree=0/0
[pid=32498] ppid=32497 vsize=9212 CPUtime=0.06
/proc/32498/stat : 32498 (aspcud-full) S 32497 32498 1733 0 -1 4202496 741 3613 0 0 0 1 3 2 20 0 1 0 118832478 9433088 365 18446744073709551615 4194304 5129932 140733307233088 140733307231744 140429248496734 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/32498/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.200355 s]
/proc/loadavg: 0.88 0.99 1.02 2/59 32498
/proc/meminfo: memFree=708472/1022884 swapFree=0/0
[pid=32498] ppid=32497 vsize=9212 CPUtime=0.06
/proc/32498/stat : 32498 (aspcud-full) S 32497 32498 1733 0 -1 4202496 741 3613 0 0 0 1 3 2 20 0 1 0 118832478 9433088 365 18446744073709551615 4194304 5129932 140733307233088 140733307231744 140429248496734 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/32498/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.300334 s]
/proc/loadavg: 0.88 0.99 1.02 2/59 32498
/proc/meminfo: memFree=708472/1022884 swapFree=0/0
[pid=32498] ppid=32497 vsize=9212 CPUtime=0.06
/proc/32498/stat : 32498 (aspcud-full) S 32497 32498 1733 0 -1 4202496 741 3613 0 0 0 1 3 2 20 0 1 0 118832478 9433088 365 18446744073709551615 4194304 5129932 140733307233088 140733307231744 140429248496734 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/32498/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.700234 s]
/proc/loadavg: 0.88 0.99 1.02 2/59 32498
/proc/meminfo: memFree=708472/1022884 swapFree=0/0
[pid=32498] ppid=32497 vsize=9212 CPUtime=0.06
/proc/32498/stat : 32498 (aspcud-full) S 32497 32498 1733 0 -1 4202496 741 3613 0 0 0 1 3 2 20 0 1 0 118832478 9433088 365 18446744073709551615 4194304 5129932 140733307233088 140733307231744 140429248496734 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/32498/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.89 0.99 1.02 2/61 32514
/proc/meminfo: memFree=674100/1022884 swapFree=0/0
[pid=32498] ppid=32497 vsize=9212 CPUtime=0.06
/proc/32498/stat : 32498 (aspcud-full) S 32497 32498 1733 0 -1 4202496 741 3613 0 0 0 1 3 2 20 0 1 0 118832478 9433088 365 18446744073709551615 4194304 5129932 140733307233088 140733307231744 140429248496734 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/32498/statm: 2303 365 303 229 0 63 0
[pid=32514] ppid=32498 vsize=53508 CPUtime=1.42
/proc/32514/stat : 32514 (cudf2lp) R 32498 32498 1733 0 -1 4202496 12642 0 0 0 134 8 0 0 20 0 1 0 118832482 54792192 10909 18446744073709551615 4194304 5690517 140733551706352 140733551702520 4363412 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/32514/statm: 13377 10909 160 366 0 13008 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 62720

[startup+3.10033 s]
/proc/loadavg: 0.89 0.99 1.02 2/61 32514
/proc/meminfo: memFree=641984/1022884 swapFree=0/0
[pid=32498] ppid=32497 vsize=9212 CPUtime=0.06
/proc/32498/stat : 32498 (aspcud-full) S 32497 32498 1733 0 -1 4202496 741 3613 0 0 0 1 3 2 20 0 1 0 118832478 9433088 365 18446744073709551615 4194304 5129932 140733307233088 140733307231744 140429248496734 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/32498/statm: 2303 365 303 229 0 63 0
[pid=32514] ppid=32498 vsize=93028 CPUtime=3.02
/proc/32514/stat : 32514 (cudf2lp) R 32498 32498 1733 0 -1 4202496 26524 0 0 0 284 18 0 0 20 0 1 0 118832482 95260672 19797 18446744073709551615 4194304 5690517 140733551706352 140733551703992 4329497 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/32514/statm: 23257 19797 160 366 0 22888 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 102240

[startup+6.30035 s]
/proc/loadavg: 0.90 0.99 1.01 2/61 32515
/proc/meminfo: memFree=654136/1022884 swapFree=0/0
[pid=32498] ppid=32497 vsize=9212 CPUtime=5.3
/proc/32498/stat : 32498 (aspcud-full) S 32497 32498 1733 0 -1 4202496 768 42934 0 0 0 1 492 37 20 0 1 0 118832478 9433088 365 18446744073709551615 4194304 5129932 140733307233088 140733307231744 140429248496734 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/32498/statm: 2303 365 303 229 0 63 0
[pid=32515] ppid=32498 vsize=28460 CPUtime=0.93
/proc/32515/stat : 32515 (gringo) R 32498 32498 1733 0 -1 4202496 7337 0 0 0 88 5 0 0 20 0 1 0 118833013 29143040 6226 18446744073709551615 4194304 6531320 140734428178800 140734428174616 4417307 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/32515/statm: 7115 6226 259 571 0 6536 0
Current children cumulated CPU time (s) 6.23
Current children cumulated vsize (KiB) 37672

[startup+12.7003 s]
/proc/loadavg: 0.98 1.00 1.02 2/61 32515
/proc/meminfo: memFree=341408/1022884 swapFree=0/0
[pid=32498] ppid=32497 vsize=9212 CPUtime=5.3
/proc/32498/stat : 32498 (aspcud-full) S 32497 32498 1733 0 -1 4202496 768 42934 0 0 0 1 492 37 20 0 1 0 118832478 9433088 365 18446744073709551615 4194304 5129932 140733307233088 140733307231744 140429248496734 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/32498/statm: 2303 365 303 229 0 63 0
[pid=32515] ppid=32498 vsize=430548 CPUtime=7.27
/proc/32515/stat : 32515 (gringo) R 32498 32498 1733 0 -1 4202496 101005 0 0 0 685 42 0 0 20 0 1 0 118833013 440881152 84530 18446744073709551615 4194304 6531320 140734428178800 140734428175784 5101987 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/32515/statm: 107637 84530 282 571 0 107058 0
Current children cumulated CPU time (s) 12.57
Current children cumulated vsize (KiB) 439760

[startup+25.5004 s]
/proc/loadavg: 1.06 1.02 1.02 2/62 32517
/proc/meminfo: memFree=431672/1022884 swapFree=0/0
[pid=32498] ppid=32497 vsize=9212 CPUtime=18.43
/proc/32498/stat : 32498 (aspcud-full) S 32497 32498 1733 0 -1 4202496 809 224487 0 0 0 1 1708 134 20 0 1 0 118832478 9433088 365 18446744073709551615 4194304 5129932 140733307233088 140733307231152 140429248496734 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/32498/statm: 2303 365 303 229 0 63 0
[pid=32516] ppid=32498 vsize=239056 CPUtime=6.69
/proc/32516/stat : 32516 (clasp) R 32498 32498 1733 0 -1 4202496 72419 0 0 0 642 27 0 0 20 0 1 0 118834349 244793344 59277 18446744073709551615 4194304 6238623 140735576083584 140735576080608 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/32516/statm: 59764 59277 263 500 0 59261 0
[pid=32517] ppid=32498 vsize=22040 CPUtime=0.02
/proc/32517/stat : 32517 (parse.py) S 32498 32498 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 118834349 22568960 1128 18446744073709551615 4194304 6642060 140734138704432 140734138702792 140474967713568 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/32517/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.14
Current children cumulated vsize (KiB) 270308

[startup+51.1004 s]
/proc/loadavg: 1.04 1.02 1.02 2/62 32517
/proc/meminfo: memFree=431300/1022884 swapFree=0/0
[pid=32498] ppid=32497 vsize=9212 CPUtime=18.43
/proc/32498/stat : 32498 (aspcud-full) S 32497 32498 1733 0 -1 4202496 809 224487 0 0 0 1 1708 134 20 0 1 0 118832478 9433088 365 18446744073709551615 4194304 5129932 140733307233088 140733307231152 140429248496734 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/32498/statm: 2303 365 303 229 0 63 0
[pid=32516] ppid=32498 vsize=239056 CPUtime=32.02
/proc/32516/stat : 32516 (clasp) R 32498 32498 1733 0 -1 4202496 72497 0 0 0 3175 27 0 0 20 0 1 0 118834349 244793344 59355 18446744073709551615 4194304 6238623 140735576083584 140735576080608 4635182 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/32516/statm: 59764 59355 263 500 0 59261 0
[pid=32517] ppid=32498 vsize=22040 CPUtime=0.02
/proc/32517/stat : 32517 (parse.py) S 32498 32498 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 118834349 22568960 1128 18446744073709551615 4194304 6642060 140734138704432 140734138702792 140474967713568 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/32517/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.47
Current children cumulated vsize (KiB) 270308

[startup+102.3 s]
/proc/loadavg: 1.01 1.01 1.02 2/62 32525
/proc/meminfo: memFree=430804/1022884 swapFree=0/0
[pid=32498] ppid=32497 vsize=9212 CPUtime=18.43
/proc/32498/stat : 32498 (aspcud-full) S 32497 32498 1733 0 -1 4202496 809 224487 0 0 0 1 1708 134 20 0 1 0 118832478 9433088 365 18446744073709551615 4194304 5129932 140733307233088 140733307231152 140429248496734 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/32498/statm: 2303 365 303 229 0 63 0
[pid=32516] ppid=32498 vsize=239056 CPUtime=82.67
/proc/32516/stat : 32516 (clasp) R 32498 32498 1733 0 -1 4202496 72497 0 0 0 8240 27 0 0 20 0 1 0 118834349 244793344 59355 18446744073709551615 4194304 6238623 140735576083584 140735576080608 4696941 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/32516/statm: 59764 59355 263 500 0 59261 0
[pid=32517] ppid=32498 vsize=22040 CPUtime=0.02
/proc/32517/stat : 32517 (parse.py) S 32498 32498 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 118834349 22568960 1128 18446744073709551615 4194304 6642060 140734138704432 140734138702792 140474967713568 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/32517/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.12
Current children cumulated vsize (KiB) 270308

[startup+162.3 s]
/proc/loadavg: 1.00 1.01 1.01 2/62 32525
/proc/meminfo: memFree=385916/1022884 swapFree=0/0
[pid=32498] ppid=32497 vsize=9212 CPUtime=18.43
/proc/32498/stat : 32498 (aspcud-full) S 32497 32498 1733 0 -1 4202496 809 224487 0 0 0 1 1708 134 20 0 1 0 118832478 9433088 365 18446744073709551615 4194304 5129932 140733307233088 140733307231152 140429248496734 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/32498/statm: 2303 365 303 229 0 63 0
[pid=32516] ppid=32498 vsize=284400 CPUtime=142.08
/proc/32516/stat : 32516 (clasp) R 32498 32498 1733 0 -1 4202496 83807 0 0 0 14173 35 0 0 20 0 1 0 118834349 291225600 70665 18446744073709551615 4194304 6238623 140735576083584 140735576080136 4669515 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/32516/statm: 71100 70665 263 500 0 70597 0
[pid=32517] ppid=32498 vsize=22040 CPUtime=0.02
/proc/32517/stat : 32517 (parse.py) S 32498 32498 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 118834349 22568960 1128 18446744073709551615 4194304 6642060 140734138704432 140734138702792 140474967713568 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/32517/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.53
Current children cumulated vsize (KiB) 315652

[startup+222.303 s]
/proc/loadavg: 1.00 1.00 1.00 2/62 32525
/proc/meminfo: memFree=331976/1022884 swapFree=0/0
[pid=32498] ppid=32497 vsize=9212 CPUtime=18.43
/proc/32498/stat : 32498 (aspcud-full) S 32497 32498 1733 0 -1 4202496 809 224487 0 0 0 1 1708 134 20 0 1 0 118832478 9433088 365 18446744073709551615 4194304 5129932 140733307233088 140733307231152 140429248496734 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/32498/statm: 2303 365 303 229 0 63 0
[pid=32516] ppid=32498 vsize=338916 CPUtime=201.61
/proc/32516/stat : 32516 (clasp) R 32498 32498 1733 0 -1 4202496 97279 0 0 0 20119 42 0 0 20 0 1 0 118834349 347049984 84137 18446744073709551615 4194304 6238623 140735576083584 140735576080608 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/32516/statm: 84729 84137 263 500 0 84226 0
[pid=32517] ppid=32498 vsize=22040 CPUtime=0.02
/proc/32517/stat : 32517 (parse.py) S 32498 32498 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 118834349 22568960 1128 18446744073709551615 4194304 6642060 140734138704432 140734138702792 140474967713568 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/32517/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.06
Current children cumulated vsize (KiB) 370168

[startup+282.3 s]
/proc/loadavg: 1.00 1.00 1.00 2/62 32525
/proc/meminfo: memFree=309656/1022884 swapFree=0/0
[pid=32498] ppid=32497 vsize=9212 CPUtime=18.43
/proc/32498/stat : 32498 (aspcud-full) S 32497 32498 1733 0 -1 4202496 809 224487 0 0 0 1 1708 134 20 0 1 0 118832478 9433088 365 18446744073709551615 4194304 5129932 140733307233088 140733307231152 140429248496734 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/32498/statm: 2303 365 303 229 0 63 0
[pid=32516] ppid=32498 vsize=361272 CPUtime=261.18
/proc/32516/stat : 32516 (clasp) R 32498 32498 1733 0 -1 4202496 102881 0 0 0 26074 44 0 0 20 0 1 0 118834349 369942528 89739 18446744073709551615 4194304 6238623 140735576083584 140735576080608 4586413 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/32516/statm: 90318 89739 264 500 0 89815 0
[pid=32517] ppid=32498 vsize=22040 CPUtime=0.02
/proc/32517/stat : 32517 (parse.py) S 32498 32498 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 118834349 22568960 1128 18446744073709551615 4194304 6642060 140734138704432 140734138702792 140474967713568 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/32517/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 279.63
Current children cumulated vsize (KiB) 392524



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.9 s]
/proc/loadavg: 1.00 1.00 1.00 2/62 32525
/proc/meminfo: memFree=309532/1022884 swapFree=0/0
[pid=32498] ppid=32497 vsize=9212 CPUtime=18.43
/proc/32498/stat : 32498 (aspcud-full) S 32497 32498 1733 0 -1 4202496 809 224487 0 0 0 1 1708 134 20 0 1 0 118832478 9433088 365 18446744073709551615 4194304 5129932 140733307233088 140733307231152 140429248496734 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/32498/statm: 2303 365 303 229 0 63 0
[pid=32516] ppid=32498 vsize=361272 CPUtime=281.63
/proc/32516/stat : 32516 (clasp) R 32498 32498 1733 0 -1 4202496 102887 0 0 0 28118 45 0 0 20 0 1 0 118834349 369942528 89745 18446744073709551615 4194304 6238623 140735576083584 140735576080608 4684829 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/32516/statm: 90318 89745 264 500 0 89815 0
[pid=32517] ppid=32498 vsize=22040 CPUtime=0.02
/proc/32517/stat : 32517 (parse.py) S 32498 32498 1733 0 -1 4202496 1318 0 0 0 1 1 0 0 20 0 1 0 118834349 22568960 1128 18446744073709551615 4194304 6642060 140734138704432 140734138702792 140474967713568 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/32517/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.08
Current children cumulated vsize (KiB) 392524

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

Child status: 0
Real time (s): 302.948
CPU time (s): 300.143
CPU user time (s): 298.291
CPU system time (s): 1.85211
CPU usage (%): 99.074
Max. virtual memory (cumulated for all children) (KiB): 807988

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.291
system time used= 1.85211
maximum resident set size= 660296
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 329827
page faults= 0
swaps= 0
block input operations= 68424
block output operations= 82480
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 84
involuntary context switches= 34380

runsolver used 0.660041 second user time and 1.30408 second system time

The end