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/difficult/rand83.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand83.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/trendy-size/upgrade/difficult/rand83.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.87 0.94 0.95 2/59 17172
/proc/meminfo: memFree=701232/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=1068 CPUtime=0
/proc/17172/stat : 17172 (aspcud-full) D 17171 17172 1750 0 -1 4194304 75 0 0 0 0 0 0 0 20 0 1 0 119601458 1093632 1 18446744073709551615 0 0 140733376883625 4294589104 4151702576 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/17172/statm: 267 1 0 0 0 28 0

[startup+0.112098 s]
/proc/loadavg: 0.87 0.94 0.95 2/59 17172
/proc/meminfo: memFree=701232/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=9212 CPUtime=0.02
/proc/17172/stat : 17172 (aspcud-full) S 17171 17172 1750 0 -1 4202496 737 3614 2 7 0 0 2 0 20 0 1 0 119601458 9433088 364 18446744073709551615 4194304 5129932 140733376882496 140733376881152 140363408475230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17172/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.20026 s]
/proc/loadavg: 0.87 0.94 0.95 2/59 17172
/proc/meminfo: memFree=701232/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=9212 CPUtime=0.02
/proc/17172/stat : 17172 (aspcud-full) S 17171 17172 1750 0 -1 4202496 737 3614 2 7 0 0 2 0 20 0 1 0 119601458 9433088 364 18446744073709551615 4194304 5129932 140733376882496 140733376881152 140363408475230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17172/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300255 s]
/proc/loadavg: 0.87 0.94 0.95 2/59 17172
/proc/meminfo: memFree=701232/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=9212 CPUtime=0.02
/proc/17172/stat : 17172 (aspcud-full) S 17171 17172 1750 0 -1 4202496 737 3614 2 7 0 0 2 0 20 0 1 0 119601458 9433088 364 18446744073709551615 4194304 5129932 140733376882496 140733376881152 140363408475230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17172/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700188 s]
/proc/loadavg: 0.87 0.94 0.95 2/59 17172
/proc/meminfo: memFree=701232/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=9212 CPUtime=0.02
/proc/17172/stat : 17172 (aspcud-full) S 17171 17172 1750 0 -1 4202496 737 3614 2 7 0 0 2 0 20 0 1 0 119601458 9433088 364 18446744073709551615 4194304 5129932 140733376882496 140733376881152 140363408475230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17172/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50025 s]
/proc/loadavg: 0.87 0.94 0.95 2/61 17188
/proc/meminfo: memFree=644052/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=9212 CPUtime=0.02
/proc/17172/stat : 17172 (aspcud-full) S 17171 17172 1750 0 -1 4202496 737 3614 2 7 0 0 2 0 20 0 1 0 119601458 9433088 364 18446744073709551615 4194304 5129932 140733376882496 140733376881152 140363408475230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17172/statm: 2303 364 303 229 0 63 0
[pid=17188] ppid=17172 vsize=50676 CPUtime=1.33
/proc/17188/stat : 17188 (cudf2lp) R 17172 17172 1750 0 -1 4202496 14929 0 1 0 128 5 0 0 20 0 1 0 119601468 51892224 11531 18446744073709551615 4194304 5690517 140733424105024 140733424102664 4970538 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/17188/statm: 12669 11531 160 366 0 12300 0
Current children cumulated CPU time (s) 1.35
Current children cumulated vsize (KiB) 59888

[startup+3.10026 s]
/proc/loadavg: 0.88 0.94 0.95 2/61 17188
/proc/meminfo: memFree=591724/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=9212 CPUtime=0.02
/proc/17172/stat : 17172 (aspcud-full) S 17171 17172 1750 0 -1 4202496 737 3614 2 7 0 0 2 0 20 0 1 0 119601458 9433088 364 18446744073709551615 4194304 5129932 140733376882496 140733376881152 140363408475230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17172/statm: 2303 364 303 229 0 63 0
[pid=17188] ppid=17172 vsize=114764 CPUtime=2.92
/proc/17188/stat : 17188 (cudf2lp) R 17172 17172 1750 0 -1 4202496 39320 0 1 0 277 15 0 0 20 0 1 0 119601468 117518336 28364 18446744073709551615 4194304 5690517 140733424105024 140733424102232 4563871 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/17188/statm: 28691 28364 174 366 0 28322 0
Current children cumulated CPU time (s) 2.94
Current children cumulated vsize (KiB) 123976

[startup+6.30024 s]
/proc/loadavg: 0.88 0.94 0.95 2/61 17189
/proc/meminfo: memFree=551300/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=9212 CPUtime=3.42
/proc/17172/stat : 17172 (aspcud-full) S 17171 17172 1750 0 -1 4202496 761 42936 2 8 0 0 322 20 20 0 1 0 119601458 9433088 364 18446744073709551615 4194304 5129932 140733376882496 140733376881152 140363408475230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17172/statm: 2303 364 303 229 0 63 0
[pid=17189] ppid=17172 vsize=213828 CPUtime=2.71
/proc/17189/stat : 17189 (gringo) R 17172 17172 1750 0 -1 4202496 52744 0 0 0 256 15 0 0 20 0 1 0 119601814 218959872 44461 18446744073709551615 4194304 6531320 140733695399744 140733695395752 4596029 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17189/statm: 53457 44461 279 571 0 52878 0
Current children cumulated CPU time (s) 6.13
Current children cumulated vsize (KiB) 223040

[startup+12.7003 s]
/proc/loadavg: 0.89 0.94 0.95 2/61 17189
/proc/meminfo: memFree=58772/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=9212 CPUtime=3.42
/proc/17172/stat : 17172 (aspcud-full) S 17171 17172 1750 0 -1 4202496 761 42936 2 8 0 0 322 20 20 0 1 0 119601458 9433088 364 18446744073709551615 4194304 5129932 140733376882496 140733376881152 140363408475230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17172/statm: 2303 364 303 229 0 63 0
[pid=17189] ppid=17172 vsize=722992 CPUtime=9.06
/proc/17189/stat : 17189 (gringo) R 17172 17172 1750 0 -1 4202496 167180 0 0 0 852 54 0 0 20 0 1 0 119601814 740343808 150704 18446744073709551615 4194304 6531320 140733695399744 140733695395608 5521049 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17189/statm: 180748 150704 282 571 0 180169 0
Current children cumulated CPU time (s) 12.48
Current children cumulated vsize (KiB) 732204

[startup+25.5004 s]
/proc/loadavg: 0.91 0.94 0.95 2/62 17191
/proc/meminfo: memFree=425060/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=9212 CPUtime=14.21
/proc/17172/stat : 17172 (aspcud-full) S 17171 17172 1750 0 -1 4202496 799 221568 2 8 0 0 1318 103 20 0 1 0 119601458 9433088 364 18446744073709551615 4194304 5129932 140733376882496 140733376880560 140363408475230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17172/statm: 2303 364 303 229 0 63 0
[pid=17190] ppid=17172 vsize=233040 CPUtime=10.8
/proc/17190/stat : 17190 (clasp) R 17172 17172 1750 0 -1 4202496 70930 0 1 0 1053 27 0 0 20 0 1 0 119602912 238632960 57831 18446744073709551615 4194304 6238623 140737227115664 140737227112688 4423392 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/17190/statm: 58260 57831 264 500 0 57757 0
[pid=17191] ppid=17172 vsize=22040 CPUtime=0.01
/proc/17191/stat : 17191 (parse.py) S 17172 17172 1750 0 -1 4202496 1306 0 13 0 0 1 0 0 20 0 1 0 119602912 22568960 1128 18446744073709551615 4194304 6642060 140735305218496 140735305216856 140449691649824 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/17191/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.02
Current children cumulated vsize (KiB) 264292

[startup+51.1004 s]
/proc/loadavg: 0.94 0.95 0.95 2/62 17191
/proc/meminfo: memFree=425060/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=9212 CPUtime=14.21
/proc/17172/stat : 17172 (aspcud-full) S 17171 17172 1750 0 -1 4202496 799 221568 2 8 0 0 1318 103 20 0 1 0 119601458 9433088 364 18446744073709551615 4194304 5129932 140733376882496 140733376880560 140363408475230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17172/statm: 2303 364 303 229 0 63 0
[pid=17190] ppid=17172 vsize=233040 CPUtime=36.14
/proc/17190/stat : 17190 (clasp) R 17172 17172 1750 0 -1 4202496 70930 0 1 0 3587 27 0 0 20 0 1 0 119602912 238632960 57831 18446744073709551615 4194304 6238623 140737227115664 140737227112688 4687675 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/17190/statm: 58260 57831 264 500 0 57757 0
[pid=17191] ppid=17172 vsize=22040 CPUtime=0.01
/proc/17191/stat : 17191 (parse.py) S 17172 17172 1750 0 -1 4202496 1306 0 13 0 0 1 0 0 20 0 1 0 119602912 22568960 1128 18446744073709551615 4194304 6642060 140735305218496 140735305216856 140449691649824 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/17191/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.36
Current children cumulated vsize (KiB) 264292

[startup+102.3 s]
/proc/loadavg: 0.97 0.95 0.95 2/62 17191
/proc/meminfo: memFree=389844/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=9212 CPUtime=14.21
/proc/17172/stat : 17172 (aspcud-full) S 17171 17172 1750 0 -1 4202496 799 221568 2 8 0 0 1318 103 20 0 1 0 119601458 9433088 364 18446744073709551615 4194304 5129932 140733376882496 140733376880560 140363408475230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17172/statm: 2303 364 303 229 0 63 0
[pid=17190] ppid=17172 vsize=267944 CPUtime=86.85
/proc/17190/stat : 17190 (clasp) R 17172 17172 1750 0 -1 4202496 79733 0 1 0 8656 29 0 0 20 0 1 0 119602912 274374656 66634 18446744073709551615 4194304 6238623 140737227115664 140737227112216 4654166 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/17190/statm: 66986 66634 264 500 0 66483 0
[pid=17191] ppid=17172 vsize=22040 CPUtime=0.01
/proc/17191/stat : 17191 (parse.py) S 17172 17172 1750 0 -1 4202496 1306 0 13 0 0 1 0 0 20 0 1 0 119602912 22568960 1128 18446744073709551615 4194304 6642060 140735305218496 140735305216856 140449691649824 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/17191/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.07
Current children cumulated vsize (KiB) 299196

[startup+162.3 s]
/proc/loadavg: 1.06 0.97 0.95 2/62 17191
/proc/meminfo: memFree=359464/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=9212 CPUtime=14.21
/proc/17172/stat : 17172 (aspcud-full) S 17171 17172 1750 0 -1 4202496 799 221568 2 8 0 0 1318 103 20 0 1 0 119601458 9433088 364 18446744073709551615 4194304 5129932 140733376882496 140733376880560 140363408475230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17172/statm: 2303 364 303 229 0 63 0
[pid=17190] ppid=17172 vsize=298224 CPUtime=146.29
/proc/17190/stat : 17190 (clasp) R 17172 17172 1750 0 -1 4202496 87300 0 1 0 14596 33 0 0 20 0 1 0 119602912 305381376 74201 18446744073709551615 4194304 6238623 140737227115664 140737227112216 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/17190/statm: 74556 74201 264 500 0 74053 0
[pid=17191] ppid=17172 vsize=22040 CPUtime=0.01
/proc/17191/stat : 17191 (parse.py) S 17172 17172 1750 0 -1 4202496 1306 0 13 0 0 1 0 0 20 0 1 0 119602912 22568960 1128 18446744073709551615 4194304 6642060 140735305218496 140735305216856 140449691649824 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/17191/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 160.51
Current children cumulated vsize (KiB) 329476

[startup+222.303 s]
/proc/loadavg: 1.14 1.00 0.97 2/62 17442
/proc/meminfo: memFree=136520/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=9212 CPUtime=14.21
/proc/17172/stat : 17172 (aspcud-full) S 17171 17172 1750 0 -1 4202496 799 221568 2 8 0 0 1318 103 20 0 1 0 119601458 9433088 364 18446744073709551615 4194304 5129932 140733376882496 140733376880560 140363408475230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17172/statm: 2303 364 303 229 0 63 0
[pid=17190] ppid=17172 vsize=322352 CPUtime=199.97
/proc/17190/stat : 17190 (clasp) R 17172 17172 1750 0 -1 4202496 93275 0 1 0 19961 36 0 0 20 0 1 0 119602912 330088448 80176 18446744073709551615 4194304 6238623 140737227115664 140737227112216 4421915 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/17190/statm: 80588 80176 264 500 0 80085 0
[pid=17191] ppid=17172 vsize=22040 CPUtime=0.01
/proc/17191/stat : 17191 (parse.py) S 17172 17172 1750 0 -1 4202496 1306 0 13 0 0 1 0 0 20 0 1 0 119602912 22568960 1128 18446744073709551615 4194304 6642060 140735305218496 140735305216856 140449691649824 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/17191/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 214.19
Current children cumulated vsize (KiB) 353604

[startup+282.3 s]
/proc/loadavg: 1.05 1.00 0.97 2/62 17442
/proc/meminfo: memFree=134164/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=9212 CPUtime=14.21
/proc/17172/stat : 17172 (aspcud-full) S 17171 17172 1750 0 -1 4202496 799 221568 2 8 0 0 1318 103 20 0 1 0 119601458 9433088 364 18446744073709551615 4194304 5129932 140733376882496 140733376880560 140363408475230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17172/statm: 2303 364 303 229 0 63 0
[pid=17190] ppid=17172 vsize=324744 CPUtime=259.5
/proc/17190/stat : 17190 (clasp) R 17172 17172 1750 0 -1 4202496 93896 0 1 0 25914 36 0 0 20 0 1 0 119602912 332537856 80797 18446744073709551615 4194304 6238623 140737227115664 140737227112216 4302413 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/17190/statm: 81186 80797 264 500 0 80683 0
[pid=17191] ppid=17172 vsize=22040 CPUtime=0.01
/proc/17191/stat : 17191 (parse.py) S 17172 17172 1750 0 -1 4202496 1306 0 13 0 0 1 0 0 20 0 1 0 119602912 22568960 1128 18446744073709551615 4194304 6642060 140735305218496 140735305216856 140449691649824 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/17191/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 273.72
Current children cumulated vsize (KiB) 355996



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+308.8 s]
/proc/loadavg: 1.03 1.00 0.97 2/62 17442
/proc/meminfo: memFree=126972/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=9212 CPUtime=14.21
/proc/17172/stat : 17172 (aspcud-full) S 17171 17172 1750 0 -1 4202496 799 221568 2 8 0 0 1318 103 20 0 1 0 119601458 9433088 364 18446744073709551615 4194304 5129932 140733376882496 140733376880560 140363408475230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17172/statm: 2303 364 303 229 0 63 0
[pid=17190] ppid=17172 vsize=332068 CPUtime=285.8
/proc/17190/stat : 17190 (clasp) R 17172 17172 1750 0 -1 4202496 95725 0 1 0 28544 36 0 0 20 0 1 0 119602912 340037632 82626 18446744073709551615 4194304 6238623 140737227115664 140737227112216 4635480 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/17190/statm: 83017 82626 264 500 0 82514 0
[pid=17191] ppid=17172 vsize=22040 CPUtime=0.01
/proc/17191/stat : 17191 (parse.py) S 17172 17172 1750 0 -1 4202496 1306 0 13 0 0 1 0 0 20 0 1 0 119602912 22568960 1128 18446744073709551615 4194304 6642060 140735305218496 140735305216856 140449691649824 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/17191/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.02
Current children cumulated vsize (KiB) 363320

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

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

[startup+308.8 s]
/proc/loadavg: 1.03 1.00 0.97 2/62 17442
/proc/meminfo: memFree=126972/1022884 swapFree=0/0
[pid=17172] ppid=17171 vsize=9212 CPUtime=14.21
/proc/17172/stat : 17172 (aspcud-full) S 17171 17172 1750 0 -1 4202496 799 221568 2 8 0 0 1318 103 20 0 1 0 119601458 9433088 364 18446744073709551615 4194304 5129932 140733376882496 140733376880560 140363408475230 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/17172/statm: 2303 364 303 229 0 63 0
[pid=17190] ppid=17172 vsize=332068 CPUtime=285.8
/proc/17190/stat : 17190 (clasp) R 17172 17172 1750 0 -1 4202496 95725 0 1 0 28544 36 0 0 20 0 1 0 119602912 340037632 82626 18446744073709551615 4194304 6238623 140737227115664 140737227112216 4635480 0 0 16781316 18946 0 0 0 17 0 0 0 2 0 0
/proc/17190/statm: 83017 82626 264 500 0 82514 0
[pid=17191] ppid=17172 vsize=22040 CPUtime=0.01
/proc/17191/stat : 17191 (parse.py) S 17172 17172 1750 0 -1 4202496 1306 0 13 0 0 1 0 0 20 0 1 0 119602912 22568960 1128 18446744073709551615 4194304 6642060 140735305218496 140735305216856 140449691649824 0 0 16777220 20994 0 0 0 17 0 0 0 9 0 0
/proc/17191/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 300.02
Current children cumulated vsize (KiB) 363320

Child status: 0
Real time (s): 308.863
CPU time (s): 300.119
CPU user time (s): 298.671
CPU system time (s): 1.44809
CPU usage (%): 97.1688
Max. virtual memory (cumulated for all children) (KiB): 783724

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 298.671
system time used= 1.44809
maximum resident set size= 648608
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 319714
page faults= 25
swaps= 0
block input operations= 70496
block output operations= 81704
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 115
involuntary context switches= 37728

runsolver used 0.664041 second user time and 1.26408 second system time

The end