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/upgrade/easy/rand507.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/easy/rand507.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/upgrade/easy/rand507.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

[startup+0 s]
/proc/loadavg: 0.85 0.94 0.92 2/60 22764
/proc/meminfo: memFree=429004/1022884 swapFree=0/0
[pid=22764] ppid=22763 vsize=3152 CPUtime=0
/proc/22764/stat : 22764 (runsolver) R 22763 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 41165025 3227648 32 18446744073709551615 134512640 134586868 4289182944 4289180992 4151288880 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/22764/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.17982 s]
/proc/loadavg: 0.85 0.94 0.92 2/60 22764
/proc/meminfo: memFree=429004/1022884 swapFree=0/0
[pid=22764] ppid=22763 vsize=9212 CPUtime=0.03
/proc/22764/stat : 22764 (aspcud-full) S 22763 22764 32685 0 -1 4202496 740 3616 0 0 0 0 2 1 20 0 1 0 41165025 9433088 364 18446744073709551615 4194304 5129932 140736999679424 140736999678080 139985824957534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/22764/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200413 s]
/proc/loadavg: 0.85 0.94 0.92 2/60 22764
/proc/meminfo: memFree=429004/1022884 swapFree=0/0
[pid=22764] ppid=22763 vsize=9212 CPUtime=0.03
/proc/22764/stat : 22764 (aspcud-full) S 22763 22764 32685 0 -1 4202496 740 3616 0 0 0 0 2 1 20 0 1 0 41165025 9433088 364 18446744073709551615 4194304 5129932 140736999679424 140736999678080 139985824957534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/22764/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.30039 s]
/proc/loadavg: 0.85 0.94 0.92 2/60 22764
/proc/meminfo: memFree=429004/1022884 swapFree=0/0
[pid=22764] ppid=22763 vsize=9212 CPUtime=0.03
/proc/22764/stat : 22764 (aspcud-full) S 22763 22764 32685 0 -1 4202496 740 3616 0 0 0 0 2 1 20 0 1 0 41165025 9433088 364 18446744073709551615 4194304 5129932 140736999679424 140736999678080 139985824957534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/22764/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700225 s]
/proc/loadavg: 0.85 0.94 0.92 2/60 22764
/proc/meminfo: memFree=429004/1022884 swapFree=0/0
[pid=22764] ppid=22763 vsize=9212 CPUtime=0.03
/proc/22764/stat : 22764 (aspcud-full) S 22763 22764 32685 0 -1 4202496 740 3616 0 0 0 0 2 1 20 0 1 0 41165025 9433088 364 18446744073709551615 4194304 5129932 140736999679424 140736999678080 139985824957534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/22764/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50033 s]
/proc/loadavg: 0.85 0.94 0.92 2/62 22780
/proc/meminfo: memFree=394880/1022884 swapFree=0/0
[pid=22764] ppid=22763 vsize=9212 CPUtime=0.03
/proc/22764/stat : 22764 (aspcud-full) S 22763 22764 32685 0 -1 4202496 740 3616 0 0 0 0 2 1 20 0 1 0 41165025 9433088 364 18446744073709551615 4194304 5129932 140736999679424 140736999678080 139985824957534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/22764/statm: 2303 364 303 229 0 63 0
[pid=22780] ppid=22764 vsize=48864 CPUtime=1.42
/proc/22780/stat : 22780 (cudf2lp) R 22764 22764 32685 0 -1 4202496 13675 0 0 0 139 3 0 0 20 0 1 0 41165028 50036736 10276 18446744073709551615 4194304 5690517 140735470481920 140735470478504 4951890 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/22780/statm: 12216 10276 159 366 0 11847 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 58076

[startup+3.10034 s]
/proc/loadavg: 0.85 0.94 0.92 2/62 22780
/proc/meminfo: memFree=364624/1022884 swapFree=0/0
[pid=22764] ppid=22763 vsize=9212 CPUtime=0.03
/proc/22764/stat : 22764 (aspcud-full) S 22763 22764 32685 0 -1 4202496 740 3616 0 0 0 0 2 1 20 0 1 0 41165025 9433088 364 18446744073709551615 4194304 5129932 140736999679424 140736999678080 139985824957534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/22764/statm: 2303 364 303 229 0 63 0
[pid=22780] ppid=22764 vsize=72092 CPUtime=2.99
/proc/22780/stat : 22780 (cudf2lp) R 22764 22764 32685 0 -1 4202496 23822 0 0 0 288 11 0 0 20 0 1 0 41165028 73822208 17758 18446744073709551615 4194304 5690517 140735470481920 140735470479288 4970346 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/22780/statm: 18023 17758 174 366 0 17654 0
Current children cumulated CPU time (s) 3.02
Current children cumulated vsize (KiB) 81304

[startup+6.30032 s]
/proc/loadavg: 0.87 0.94 0.92 2/62 22781
/proc/meminfo: memFree=301136/1022884 swapFree=0/0
[pid=22764] ppid=22763 vsize=9212 CPUtime=3.13
/proc/22764/stat : 22764 (aspcud-full) S 22763 22764 32685 0 -1 4202496 766 27440 0 0 0 0 299 14 20 0 1 0 41165025 9433088 364 18446744073709551615 4194304 5129932 140736999679424 140736999678080 139985824957534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/22764/statm: 2303 364 303 229 0 63 0
[pid=22781] ppid=22764 vsize=161640 CPUtime=3.06
/proc/22781/stat : 22781 (gringo) R 22764 22764 32685 0 -1 4202496 40704 0 0 0 292 14 0 0 20 0 1 0 41165346 165519360 36261 18446744073709551615 4194304 6531320 140733899404112 140733899400120 4593322 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/22781/statm: 40410 36261 281 571 0 39831 0
Current children cumulated CPU time (s) 6.19
Current children cumulated vsize (KiB) 170852

[startup+12.7004 s]
/proc/loadavg: 0.96 0.96 0.93 2/63 22783
/proc/meminfo: memFree=269116/1022884 swapFree=0/0
[pid=22764] ppid=22763 vsize=9212 CPUtime=10.52
/proc/22764/stat : 22764 (aspcud-full) S 22763 22764 32685 0 -1 4202496 807 135250 0 0 0 0 980 72 20 0 1 0 41165025 9433088 364 18446744073709551615 4194304 5129932 140736999679424 140736999677488 139985824957534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/22764/statm: 2303 364 303 229 0 63 0
[pid=22782] ppid=22764 vsize=138604 CPUtime=1.96
/proc/22782/stat : 22782 (clasp) R 22764 22764 32685 0 -1 4202496 40263 0 0 0 184 12 0 0 20 0 1 0 41166094 141930496 34103 18446744073709551615 4194304 6238623 140733876646208 140733876643232 4371507 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/22782/statm: 34651 34103 263 500 0 34148 0
[pid=22783] ppid=22764 vsize=22040 CPUtime=0.01
/proc/22783/stat : 22783 (parse.py) S 22764 22764 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 41166094 22568960 1128 18446744073709551615 4194304 6642060 140737058286064 140737058284424 139980028798752 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/22783/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.49
Current children cumulated vsize (KiB) 169856

[startup+25.5004 s]
/proc/loadavg: 0.97 0.96 0.93 2/63 22783
/proc/meminfo: memFree=268124/1022884 swapFree=0/0
[pid=22764] ppid=22763 vsize=9212 CPUtime=10.52
/proc/22764/stat : 22764 (aspcud-full) S 22763 22764 32685 0 -1 4202496 807 135250 0 0 0 0 980 72 20 0 1 0 41165025 9433088 364 18446744073709551615 4194304 5129932 140736999679424 140736999677488 139985824957534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/22764/statm: 2303 364 303 229 0 63 0
[pid=22782] ppid=22764 vsize=138604 CPUtime=14.67
/proc/22782/stat : 22782 (clasp) R 22764 22764 32685 0 -1 4202496 40504 0 0 0 1451 16 0 0 20 0 1 0 41166094 141930496 34344 18446744073709551615 4194304 6238623 140733876646208 140733876643232 4635703 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/22782/statm: 34651 34344 263 500 0 34148 0
[pid=22783] ppid=22764 vsize=22040 CPUtime=0.01
/proc/22783/stat : 22783 (parse.py) S 22764 22764 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 41166094 22568960 1128 18446744073709551615 4194304 6642060 140737058286064 140737058284424 139980028798752 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/22783/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.2
Current children cumulated vsize (KiB) 169856

[startup+51.1004 s]
/proc/loadavg: 0.98 0.96 0.93 2/63 22783
/proc/meminfo: memFree=268000/1022884 swapFree=0/0
[pid=22764] ppid=22763 vsize=9212 CPUtime=10.52
/proc/22764/stat : 22764 (aspcud-full) S 22763 22764 32685 0 -1 4202496 807 135250 0 0 0 0 980 72 20 0 1 0 41165025 9433088 364 18446744073709551615 4194304 5129932 140736999679424 140736999677488 139985824957534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/22764/statm: 2303 364 303 229 0 63 0
[pid=22782] ppid=22764 vsize=138604 CPUtime=40.07
/proc/22782/stat : 22782 (clasp) R 22764 22764 32685 0 -1 4202496 40504 0 0 0 3981 26 0 0 20 0 1 0 41166094 141930496 34344 18446744073709551615 4194304 6238623 140733876646208 140733876643232 4422166 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/22782/statm: 34651 34344 263 500 0 34148 0
[pid=22783] ppid=22764 vsize=22040 CPUtime=0.01
/proc/22783/stat : 22783 (parse.py) S 22764 22764 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 41166094 22568960 1128 18446744073709551615 4194304 6642060 140737058286064 140737058284424 139980028798752 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/22783/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.6
Current children cumulated vsize (KiB) 169856

[startup+102.3 s]
/proc/loadavg: 0.99 0.97 0.93 2/63 22783
/proc/meminfo: memFree=243944/1022884 swapFree=0/0
[pid=22764] ppid=22763 vsize=9212 CPUtime=10.52
/proc/22764/stat : 22764 (aspcud-full) S 22763 22764 32685 0 -1 4202496 807 135250 0 0 0 0 980 72 20 0 1 0 41165025 9433088 364 18446744073709551615 4194304 5129932 140736999679424 140736999677488 139985824957534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/22764/statm: 2303 364 303 229 0 63 0
[pid=22782] ppid=22764 vsize=162516 CPUtime=90.87
/proc/22782/stat : 22782 (clasp) R 22764 22764 32685 0 -1 4202496 46507 0 0 0 9045 42 0 0 20 0 1 0 41166094 166416384 40347 18446744073709551615 4194304 6238623 140733876646208 140733876642760 4306744 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/22782/statm: 40629 40347 264 500 0 40126 0
[pid=22783] ppid=22764 vsize=22040 CPUtime=0.01
/proc/22783/stat : 22783 (parse.py) S 22764 22764 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 41166094 22568960 1128 18446744073709551615 4194304 6642060 140737058286064 140737058284424 139980028798752 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/22783/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.4
Current children cumulated vsize (KiB) 193768

[startup+162.3 s]
/proc/loadavg: 0.99 0.97 0.93 2/63 22783
/proc/meminfo: memFree=172644/1022884 swapFree=0/0
[pid=22764] ppid=22763 vsize=9212 CPUtime=10.52
/proc/22764/stat : 22764 (aspcud-full) S 22763 22764 32685 0 -1 4202496 807 135250 0 0 0 0 980 72 20 0 1 0 41165025 9433088 364 18446744073709551615 4194304 5129932 140736999679424 140736999677488 139985824957534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/22764/statm: 2303 364 303 229 0 63 0
[pid=22782] ppid=22764 vsize=233672 CPUtime=150.4
/proc/22782/stat : 22782 (clasp) R 22764 22764 32685 0 -1 4202496 64282 0 0 0 14979 61 0 0 20 0 1 0 41166094 239280128 58122 18446744073709551615 4194304 6238623 140733876646208 140733876642760 4677371 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/22782/statm: 58418 58122 264 500 0 57915 0
[pid=22783] ppid=22764 vsize=22040 CPUtime=0.01
/proc/22783/stat : 22783 (parse.py) S 22764 22764 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 41166094 22568960 1128 18446744073709551615 4194304 6642060 140737058286064 140737058284424 139980028798752 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/22783/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.93
Current children cumulated vsize (KiB) 264924

[startup+222.309 s]
/proc/loadavg: 0.99 0.97 0.93 2/63 22794
/proc/meminfo: memFree=134576/1022884 swapFree=0/0
[pid=22764] ppid=22763 vsize=9212 CPUtime=10.52
/proc/22764/stat : 22764 (aspcud-full) S 22763 22764 32685 0 -1 4202496 807 135250 0 0 0 0 980 72 20 0 1 0 41165025 9433088 364 18446744073709551615 4194304 5129932 140736999679424 140736999677488 139985824957534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/22764/statm: 2303 364 303 229 0 63 0
[pid=22782] ppid=22764 vsize=271176 CPUtime=209.91
/proc/22782/stat : 22782 (clasp) R 22764 22764 32685 0 -1 4202496 73649 0 0 0 20912 79 0 0 20 0 1 0 41166094 277684224 67489 18446744073709551615 4194304 6238623 140733876646208 140733876642760 4306741 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/22782/statm: 67794 67489 264 500 0 67291 0
[pid=22783] ppid=22764 vsize=22040 CPUtime=0.01
/proc/22783/stat : 22783 (parse.py) S 22764 22764 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 41166094 22568960 1128 18446744073709551615 4194304 6642060 140737058286064 140737058284424 139980028798752 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/22783/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 220.44
Current children cumulated vsize (KiB) 302428

[startup+282.3 s]
/proc/loadavg: 0.99 0.97 0.93 2/63 22794
/proc/meminfo: memFree=79644/1022884 swapFree=0/0
[pid=22764] ppid=22763 vsize=9212 CPUtime=10.52
/proc/22764/stat : 22764 (aspcud-full) S 22763 22764 32685 0 -1 4202496 807 135250 0 0 0 0 980 72 20 0 1 0 41165025 9433088 364 18446744073709551615 4194304 5129932 140736999679424 140736999677488 139985824957534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/22764/statm: 2303 364 303 229 0 63 0
[pid=22782] ppid=22764 vsize=326432 CPUtime=269.47
/proc/22782/stat : 22782 (clasp) R 22764 22764 32685 0 -1 4202496 87481 0 0 0 26847 100 0 0 20 0 1 0 41166094 334266368 81321 18446744073709551615 4194304 6238623 140733876646208 140733876642760 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/22782/statm: 81608 81321 264 500 0 81105 0
[pid=22783] ppid=22764 vsize=22040 CPUtime=0.01
/proc/22783/stat : 22783 (parse.py) S 22764 22764 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 41166094 22568960 1128 18446744073709551615 4194304 6642060 140737058286064 140737058284424 139980028798752 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/22783/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 280
Current children cumulated vsize (KiB) 357684



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+302.5 s]
/proc/loadavg: 0.99 0.97 0.93 2/63 22794
/proc/meminfo: memFree=79644/1022884 swapFree=0/0
[pid=22764] ppid=22763 vsize=9212 CPUtime=10.52
/proc/22764/stat : 22764 (aspcud-full) S 22763 22764 32685 0 -1 4202496 807 135250 0 0 0 0 980 72 20 0 1 0 41165025 9433088 364 18446744073709551615 4194304 5129932 140736999679424 140736999677488 139985824957534 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/22764/statm: 2303 364 303 229 0 63 0
[pid=22782] ppid=22764 vsize=326432 CPUtime=289.52
/proc/22782/stat : 22782 (clasp) R 22764 22764 32685 0 -1 4202496 87481 0 0 0 28849 103 0 0 20 0 1 0 41166094 334266368 81321 18446744073709551615 4194304 6238623 140733876646208 140733876642760 4332464 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/22782/statm: 81608 81321 264 500 0 81105 0
[pid=22783] ppid=22764 vsize=22040 CPUtime=0.01
/proc/22783/stat : 22783 (parse.py) S 22764 22764 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 41166094 22568960 1128 18446744073709551615 4194304 6642060 140737058286064 140737058284424 139980028798752 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/22783/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.05
Current children cumulated vsize (KiB) 357684

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.574
CPU time (s): 300.151
CPU user time (s): 298.327
CPU system time (s): 1.82411
CPU usage (%): 99.199
Max. virtual memory (cumulated for all children) (KiB): 456876

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.327
system time used= 1.82411
maximum resident set size= 397064
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 225173
page faults= 0
swaps= 0
block input operations= 42368
block output operations= 46832
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 80
involuntary context switches= 4723

runsolver used 0.992062 second user time and 1.30008 second system time

The end