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/trendy-size/real/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/real/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/trendy-size/real/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.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.97 0.97 0.95 2/60 23936
/proc/meminfo: memFree=668620/1022884 swapFree=0/0
[pid=23936] ppid=23935 vsize=3152 CPUtime=0
/proc/23936/stat : 23936 (runsolver) R 23935 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 41465273 3227648 33 18446744073709551615 134512640 134586868 4287817472 4287815520 4151387184 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/23936/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.162638 s]
/proc/loadavg: 0.97 0.97 0.95 2/60 23936
/proc/meminfo: memFree=668620/1022884 swapFree=0/0
[pid=23936] ppid=23935 vsize=9212 CPUtime=0.04
/proc/23936/stat : 23936 (aspuncud-full) S 23935 23936 32685 0 -1 4202496 694 2812 0 0 0 0 2 2 20 0 1 0 41465273 9433088 364 18446744073709551615 4194304 5129932 140733848579392 140733848578048 139766163088478 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23936/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200327 s]
/proc/loadavg: 0.97 0.97 0.95 2/60 23936
/proc/meminfo: memFree=668620/1022884 swapFree=0/0
[pid=23936] ppid=23935 vsize=9212 CPUtime=0.04
/proc/23936/stat : 23936 (aspuncud-full) S 23935 23936 32685 0 -1 4202496 694 2812 0 0 0 0 2 2 20 0 1 0 41465273 9433088 364 18446744073709551615 4194304 5129932 140733848579392 140733848578048 139766163088478 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23936/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300309 s]
/proc/loadavg: 0.97 0.97 0.95 2/60 23936
/proc/meminfo: memFree=668620/1022884 swapFree=0/0
[pid=23936] ppid=23935 vsize=9212 CPUtime=0.04
/proc/23936/stat : 23936 (aspuncud-full) S 23935 23936 32685 0 -1 4202496 694 2812 0 0 0 0 2 2 20 0 1 0 41465273 9433088 364 18446744073709551615 4194304 5129932 140733848579392 140733848578048 139766163088478 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23936/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700236 s]
/proc/loadavg: 0.97 0.97 0.95 2/60 23936
/proc/meminfo: memFree=668620/1022884 swapFree=0/0
[pid=23936] ppid=23935 vsize=9212 CPUtime=0.04
/proc/23936/stat : 23936 (aspuncud-full) S 23935 23936 32685 0 -1 4202496 694 2812 0 0 0 0 2 2 20 0 1 0 41465273 9433088 364 18446744073709551615 4194304 5129932 140733848579392 140733848578048 139766163088478 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23936/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.97 0.97 0.95 2/62 23949
/proc/meminfo: memFree=633504/1022884 swapFree=0/0
[pid=23936] ppid=23935 vsize=9212 CPUtime=0.04
/proc/23936/stat : 23936 (aspuncud-full) S 23935 23936 32685 0 -1 4202496 694 2812 0 0 0 0 2 2 20 0 1 0 41465273 9433088 364 18446744073709551615 4194304 5129932 140733848579392 140733848578048 139766163088478 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23936/statm: 2303 364 303 229 0 63 0
[pid=23949] ppid=23936 vsize=58160 CPUtime=1.4
/proc/23949/stat : 23949 (cudf2lp) R 23936 23936 32685 0 -1 4202496 14348 0 0 0 130 10 0 0 20 0 1 0 41465276 59555840 12615 18446744073709551615 4194304 5690517 140733770892848 140733770889016 4297208 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/23949/statm: 14540 12615 160 366 0 14171 0
Current children cumulated CPU time (s) 1.44
Current children cumulated vsize (KiB) 67372

[startup+3.10036 s]
/proc/loadavg: 0.97 0.97 0.95 2/62 23949
/proc/meminfo: memFree=600644/1022884 swapFree=0/0
[pid=23936] ppid=23935 vsize=9212 CPUtime=0.04
/proc/23936/stat : 23936 (aspuncud-full) S 23935 23936 32685 0 -1 4202496 694 2812 0 0 0 0 2 2 20 0 1 0 41465273 9433088 364 18446744073709551615 4194304 5129932 140733848579392 140733848578048 139766163088478 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23936/statm: 2303 364 303 229 0 63 0
[pid=23949] ppid=23936 vsize=78192 CPUtime=2.99
/proc/23949/stat : 23949 (cudf2lp) R 23936 23936 32685 0 -1 4202496 25440 0 0 0 280 19 0 0 20 0 1 0 41465276 80068608 19275 18446744073709551615 4194304 5690517 140733770892848 140733770889832 4314567 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/23949/statm: 19548 19275 174 366 0 19179 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 87404

[startup+6.30026 s]
/proc/loadavg: 0.97 0.97 0.95 2/62 23950
/proc/meminfo: memFree=492516/1022884 swapFree=0/0
[pid=23936] ppid=23935 vsize=9212 CPUtime=3.24
/proc/23936/stat : 23936 (aspuncud-full) S 23935 23936 32685 0 -1 4202496 721 28254 0 0 0 1 300 23 20 0 1 0 41465273 9433088 364 18446744073709551615 4194304 5129932 140733848579392 140733848578048 139766163088478 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23936/statm: 2303 364 303 229 0 63 0
[pid=23950] ppid=23936 vsize=213500 CPUtime=2.97
/proc/23950/stat : 23950 (gringo) R 23936 23936 32685 0 -1 4202496 54581 0 0 0 281 16 0 0 20 0 1 0 41465604 218624000 46299 18446744073709551615 4194304 6531320 140735764528224 140735764525208 4306195 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23950/statm: 53375 46299 280 571 0 52796 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 222712

[startup+12.7003 s]
/proc/loadavg: 0.97 0.97 0.95 2/63 23952
/proc/meminfo: memFree=442660/1022884 swapFree=0/0
[pid=23936] ppid=23935 vsize=9212 CPUtime=9.59
/proc/23936/stat : 23936 (aspuncud-full) S 23935 23936 32685 0 -1 4202496 760 168465 0 0 0 1 885 73 20 0 1 0 41465273 9433088 364 18446744073709551615 4194304 5129932 140733848579392 140733848577456 139766163088478 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23936/statm: 2303 364 303 229 0 63 0
[pid=23951] ppid=23936 vsize=174544 CPUtime=2.97
/proc/23951/stat : 23951 (unclasp) R 23936 23936 32685 0 -1 4202496 51593 0 0 0 281 16 0 0 20 0 1 0 41466242 178733056 42865 18446744073709551615 4194304 6012874 140733506980672 140733506979992 4548180 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23951/statm: 43636 42865 230 444 0 43184 0
[pid=23952] ppid=23936 vsize=22188 CPUtime=0.01
/proc/23952/stat : 23952 (parse.py) S 23936 23936 32685 0 -1 4202496 1343 0 0 0 0 1 0 0 20 0 1 0 41466242 22720512 1153 18446744073709551615 4194304 6642060 140737412591152 140737412589032 139853428909856 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23952/statm: 5547 1153 508 598 0 633 0
Current children cumulated CPU time (s) 12.57
Current children cumulated vsize (KiB) 205944

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

[startup+12.8004 s]
/proc/loadavg: 0.97 0.97 0.95 2/63 23952
/proc/meminfo: memFree=442660/1022884 swapFree=0/0
[pid=23936] ppid=23935 vsize=9212 CPUtime=9.59
/proc/23936/stat : 23936 (aspuncud-full) S 23935 23936 32685 0 -1 4202496 760 168465 0 0 0 1 885 73 20 0 1 0 41465273 9433088 364 18446744073709551615 4194304 5129932 140733848579392 140733848577456 139766163088478 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23936/statm: 2303 364 303 229 0 63 0
[pid=23951] ppid=23936 vsize=174544 CPUtime=3.07
/proc/23951/stat : 23951 (unclasp) R 23936 23936 32685 0 -1 4202496 51593 0 0 0 291 16 0 0 20 0 1 0 41466242 178733056 42865 18446744073709551615 4194304 6012874 140733506980672 140733506979992 4855840 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23951/statm: 43636 42865 230 444 0 43184 0
[pid=23952] ppid=23936 vsize=22188 CPUtime=0.01
/proc/23952/stat : 23952 (parse.py) S 23936 23936 32685 0 -1 4202496 1343 0 0 0 0 1 0 0 20 0 1 0 41466242 22720512 1153 18446744073709551615 4194304 6642060 140737412591152 140737412589032 139853428909856 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23952/statm: 5547 1153 508 598 0 633 0
Current children cumulated CPU time (s) 12.67
Current children cumulated vsize (KiB) 205944

[startup+19.2003 s]
/proc/loadavg: 0.97 0.97 0.95 2/63 23952
/proc/meminfo: memFree=442784/1022884 swapFree=0/0
[pid=23936] ppid=23935 vsize=9212 CPUtime=9.59
/proc/23936/stat : 23936 (aspuncud-full) S 23935 23936 32685 0 -1 4202496 760 168465 0 0 0 1 885 73 20 0 1 0 41465273 9433088 364 18446744073709551615 4194304 5129932 140733848579392 140733848577456 139766163088478 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23936/statm: 2303 364 303 229 0 63 0
[pid=23951] ppid=23936 vsize=174544 CPUtime=9.43
/proc/23951/stat : 23951 (unclasp) R 23936 23936 32685 0 -1 4202496 51629 0 0 0 927 16 0 0 20 0 1 0 41466242 178733056 42901 18446744073709551615 4194304 6012874 140733506980672 140733506979992 4300065 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23951/statm: 43636 42901 230 444 0 43184 0
[pid=23952] ppid=23936 vsize=22368 CPUtime=0.01
/proc/23952/stat : 23952 (parse.py) S 23936 23936 32685 0 -1 4202496 1399 0 0 0 0 1 0 0 20 0 1 0 41466242 22904832 1209 18446744073709551615 4194304 6642060 140737412591152 140737412589112 139853428909856 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23952/statm: 5592 1209 508 598 0 678 0
Current children cumulated CPU time (s) 19.03
Current children cumulated vsize (KiB) 206124

[startup+22.4003 s]
/proc/loadavg: 0.97 0.97 0.95 2/63 23952
/proc/meminfo: memFree=442784/1022884 swapFree=0/0
[pid=23936] ppid=23935 vsize=9212 CPUtime=9.59
/proc/23936/stat : 23936 (aspuncud-full) S 23935 23936 32685 0 -1 4202496 760 168465 0 0 0 1 885 73 20 0 1 0 41465273 9433088 364 18446744073709551615 4194304 5129932 140733848579392 140733848577456 139766163088478 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23936/statm: 2303 364 303 229 0 63 0
[pid=23951] ppid=23936 vsize=174544 CPUtime=12.61
/proc/23951/stat : 23951 (unclasp) R 23936 23936 32685 0 -1 4202496 51631 0 0 0 1245 16 0 0 20 0 1 0 41466242 178733056 42903 18446744073709551615 4194304 6012874 140733506980672 140733506979992 4548565 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23951/statm: 43636 42903 230 444 0 43184 0
[pid=23952] ppid=23936 vsize=22368 CPUtime=0.01
/proc/23952/stat : 23952 (parse.py) S 23936 23936 32685 0 -1 4202496 1399 0 0 0 0 1 0 0 20 0 1 0 41466242 22904832 1209 18446744073709551615 4194304 6642060 140737412591152 140737412589112 139853428909856 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23952/statm: 5592 1209 508 598 0 678 0
Current children cumulated CPU time (s) 22.21
Current children cumulated vsize (KiB) 206124

[startup+24.0003 s]
/proc/loadavg: 0.97 0.97 0.95 2/63 23952
/proc/meminfo: memFree=442784/1022884 swapFree=0/0
[pid=23936] ppid=23935 vsize=9212 CPUtime=9.59
/proc/23936/stat : 23936 (aspuncud-full) S 23935 23936 32685 0 -1 4202496 760 168465 0 0 0 1 885 73 20 0 1 0 41465273 9433088 364 18446744073709551615 4194304 5129932 140733848579392 140733848577456 139766163088478 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23936/statm: 2303 364 303 229 0 63 0
[pid=23951] ppid=23936 vsize=174544 CPUtime=14.2
/proc/23951/stat : 23951 (unclasp) R 23936 23936 32685 0 -1 4202496 51639 0 0 0 1404 16 0 0 20 0 1 0 41466242 178733056 42911 18446744073709551615 4194304 6012874 140733506980672 140733506979992 4548906 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23951/statm: 43636 42911 230 444 0 43184 0
[pid=23952] ppid=23936 vsize=22368 CPUtime=0.01
/proc/23952/stat : 23952 (parse.py) S 23936 23936 32685 0 -1 4202496 1399 0 0 0 0 1 0 0 20 0 1 0 41466242 22904832 1209 18446744073709551615 4194304 6642060 140737412591152 140737412589112 139853428909856 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23952/statm: 5592 1209 508 598 0 678 0
Current children cumulated CPU time (s) 23.8
Current children cumulated vsize (KiB) 206124

[startup+24.8004 s]
/proc/loadavg: 0.98 0.97 0.95 2/63 23952
/proc/meminfo: memFree=442784/1022884 swapFree=0/0
[pid=23936] ppid=23935 vsize=9212 CPUtime=9.59
/proc/23936/stat : 23936 (aspuncud-full) S 23935 23936 32685 0 -1 4202496 760 168465 0 0 0 1 885 73 20 0 1 0 41465273 9433088 364 18446744073709551615 4194304 5129932 140733848579392 140733848577456 139766163088478 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23936/statm: 2303 364 303 229 0 63 0
[pid=23951] ppid=23936 vsize=174544 CPUtime=15
/proc/23951/stat : 23951 (unclasp) R 23936 23936 32685 0 -1 4202496 51641 0 0 0 1484 16 0 0 20 0 1 0 41466242 178733056 42913 18446744073709551615 4194304 6012874 140733506980672 140733506979992 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23951/statm: 43636 42913 230 444 0 43184 0
[pid=23952] ppid=23936 vsize=22368 CPUtime=0.01
/proc/23952/stat : 23952 (parse.py) S 23936 23936 32685 0 -1 4202496 1399 0 0 0 0 1 0 0 20 0 1 0 41466242 22904832 1209 18446744073709551615 4194304 6642060 140737412591152 140737412589112 139853428909856 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23952/statm: 5592 1209 508 598 0 678 0
Current children cumulated CPU time (s) 24.6
Current children cumulated vsize (KiB) 206124

[startup+25.0003 s]
/proc/loadavg: 0.98 0.97 0.95 2/63 23952
/proc/meminfo: memFree=442784/1022884 swapFree=0/0
[pid=23936] ppid=23935 vsize=9212 CPUtime=9.59
/proc/23936/stat : 23936 (aspuncud-full) S 23935 23936 32685 0 -1 4202496 760 168465 0 0 0 1 885 73 20 0 1 0 41465273 9433088 364 18446744073709551615 4194304 5129932 140733848579392 140733848577456 139766163088478 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23936/statm: 2303 364 303 229 0 63 0
[pid=23951] ppid=23936 vsize=174544 CPUtime=15.2
/proc/23951/stat : 23951 (unclasp) R 23936 23936 32685 0 -1 4202496 51641 0 0 0 1504 16 0 0 20 0 1 0 41466242 178733056 42913 18446744073709551615 4194304 6012874 140733506980672 140733506979992 4548182 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23951/statm: 43636 42913 230 444 0 43184 0
[pid=23952] ppid=23936 vsize=22368 CPUtime=0.01
/proc/23952/stat : 23952 (parse.py) S 23936 23936 32685 0 -1 4202496 1399 0 0 0 0 1 0 0 20 0 1 0 41466242 22904832 1209 18446744073709551615 4194304 6642060 140737412591152 140737412589112 139853428909856 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23952/statm: 5592 1209 508 598 0 678 0
Current children cumulated CPU time (s) 24.8
Current children cumulated vsize (KiB) 206124

[startup+25.1004 s]
/proc/loadavg: 0.98 0.97 0.95 2/63 23952
/proc/meminfo: memFree=442784/1022884 swapFree=0/0
[pid=23936] ppid=23935 vsize=9212 CPUtime=9.59
/proc/23936/stat : 23936 (aspuncud-full) S 23935 23936 32685 0 -1 4202496 760 168465 0 0 0 1 885 73 20 0 1 0 41465273 9433088 364 18446744073709551615 4194304 5129932 140733848579392 140733848577456 139766163088478 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23936/statm: 2303 364 303 229 0 63 0
[pid=23951] ppid=23936 vsize=174544 CPUtime=15.3
/proc/23951/stat : 23951 (unclasp) R 23936 23936 32685 0 -1 4202496 51641 0 0 0 1514 16 0 0 20 0 1 0 41466242 178733056 42913 18446744073709551615 4194304 6012874 140733506980672 140733506979992 4307064 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23951/statm: 43636 42913 230 444 0 43184 0
[pid=23952] ppid=23936 vsize=22524 CPUtime=0.01
/proc/23952/stat : 23952 (parse.py) S 23936 23936 32685 0 -1 4202496 1411 0 0 0 0 1 0 0 20 0 1 0 41466242 23064576 1221 18446744073709551615 4194304 6642060 140737412591152 140737412589160 139853428909856 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23952/statm: 5631 1221 508 598 0 717 0
Current children cumulated CPU time (s) 24.9
Current children cumulated vsize (KiB) 206280

Child status: 0
Real time (s): 25.1949
CPU time (s): 25.0256
CPU user time (s): 24.0415
CPU system time (s): 0.984061
CPU usage (%): 99.328
Max. virtual memory (cumulated for all children) (KiB): 598340

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 24.0415
system time used= 0.984061
maximum resident set size= 494928
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 222570
page faults= 0
swaps= 0
block input operations= 43856
block output operations= 59000
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 207
involuntary context switches= 555

runsolver used 0.028001 second user time and 0.116007 second system time

The end