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/301cbe92-a79c-11e0-9181-00163e1e087d.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/real/301cbe92-a79c-11e0-9181-00163e1e087d.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/trendy-size/real/301cbe92-a79c-11e0-9181-00163e1e087d.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: 1.06 1.02 0.98 2/59 17942
/proc/meminfo: memFree=423516/1022884 swapFree=0/0
[pid=17942] ppid=17941 vsize=3152 CPUtime=0
/proc/17942/stat : 17942 (runsolver) R 17941 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 119700058 3227648 32 18446744073709551615 134512640 134586868 4287450352 4287448400 4151280688 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/17942/statm: 788 32 0 19 0 73 0

[startup+0.140386 s]
/proc/loadavg: 1.06 1.02 0.98 2/59 17942
/proc/meminfo: memFree=423516/1022884 swapFree=0/0
[pid=17942] ppid=17941 vsize=9212 CPUtime=0.03
/proc/17942/stat : 17942 (aspuncud-full) S 17941 17942 1750 0 -1 4202496 700 2806 0 0 0 0 2 1 20 0 1 0 119700058 9433088 365 18446744073709551615 4194304 5129932 140734592321360 140734592320016 140287784526942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17942/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200343 s]
/proc/loadavg: 1.06 1.02 0.98 2/59 17942
/proc/meminfo: memFree=423516/1022884 swapFree=0/0
[pid=17942] ppid=17941 vsize=9212 CPUtime=0.03
/proc/17942/stat : 17942 (aspuncud-full) S 17941 17942 1750 0 -1 4202496 700 2806 0 0 0 0 2 1 20 0 1 0 119700058 9433088 365 18446744073709551615 4194304 5129932 140734592321360 140734592320016 140287784526942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17942/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300284 s]
/proc/loadavg: 1.06 1.02 0.98 2/59 17942
/proc/meminfo: memFree=423516/1022884 swapFree=0/0
[pid=17942] ppid=17941 vsize=9212 CPUtime=0.03
/proc/17942/stat : 17942 (aspuncud-full) S 17941 17942 1750 0 -1 4202496 700 2806 0 0 0 0 2 1 20 0 1 0 119700058 9433088 365 18446744073709551615 4194304 5129932 140734592321360 140734592320016 140287784526942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17942/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700207 s]
/proc/loadavg: 1.06 1.02 0.98 2/59 17942
/proc/meminfo: memFree=423516/1022884 swapFree=0/0
[pid=17942] ppid=17941 vsize=9212 CPUtime=0.03
/proc/17942/stat : 17942 (aspuncud-full) S 17941 17942 1750 0 -1 4202496 700 2806 0 0 0 0 2 1 20 0 1 0 119700058 9433088 365 18446744073709551615 4194304 5129932 140734592321360 140734592320016 140287784526942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17942/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50027 s]
/proc/loadavg: 1.06 1.02 0.98 2/61 17955
/proc/meminfo: memFree=381580/1022884 swapFree=0/0
[pid=17942] ppid=17941 vsize=9212 CPUtime=0.03
/proc/17942/stat : 17942 (aspuncud-full) S 17941 17942 1750 0 -1 4202496 700 2806 0 0 0 0 2 1 20 0 1 0 119700058 9433088 365 18446744073709551615 4194304 5129932 140734592321360 140734592320016 140287784526942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17942/statm: 2303 365 303 229 0 63 0
[pid=17955] ppid=17942 vsize=50440 CPUtime=1.31
/proc/17955/stat : 17955 (cudf2lp) R 17942 17942 1750 0 -1 4202496 14517 0 0 0 126 5 0 0 20 0 1 0 119700061 51650560 11118 18446744073709551615 4194304 5690517 140736028057344 140736028054984 4329559 0 0 16781316 0 0 0 0 17 0 0 0 13 0 0
/proc/17955/statm: 12610 11118 160 366 0 12241 0
Current children cumulated CPU time (s) 1.34
Current children cumulated vsize (KiB) 59652

[startup+3.10031 s]
/proc/loadavg: 1.05 1.02 0.98 2/61 17955
/proc/meminfo: memFree=331484/1022884 swapFree=0/0
[pid=17942] ppid=17941 vsize=9212 CPUtime=2.8
/proc/17942/stat : 17942 (aspuncud-full) S 17941 17942 1750 0 -1 4202496 727 29081 0 0 0 0 264 16 20 0 1 0 119700058 9433088 365 18446744073709551615 4194304 5129932 140734592321360 140734592320016 140287784526942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17942/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 2.8
Current children cumulated vsize (KiB) 9212

[startup+6.30031 s]
/proc/loadavg: 1.05 1.02 0.98 2/61 17956
/proc/meminfo: memFree=306064/1022884 swapFree=0/0
[pid=17942] ppid=17941 vsize=9212 CPUtime=2.8
/proc/17942/stat : 17942 (aspuncud-full) S 17941 17942 1750 0 -1 4202496 727 29081 0 0 0 0 264 16 20 0 1 0 119700058 9433088 365 18446744073709551615 4194304 5129932 140734592321360 140734592320016 140287784526942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17942/statm: 2303 365 303 229 0 63 0
[pid=17956] ppid=17942 vsize=149560 CPUtime=3.18
/proc/17956/stat : 17956 (gringo) R 17942 17942 1750 0 -1 4202496 36656 0 0 0 300 18 0 0 20 0 1 0 119700365 153149440 32470 18446744073709551615 4194304 6531320 140735707101088 140735707097704 4593393 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17956/statm: 37390 32470 281 571 0 36811 0
Current children cumulated CPU time (s) 5.98
Current children cumulated vsize (KiB) 158772

[startup+12.7004 s]
/proc/loadavg: 1.04 1.01 0.98 2/62 17958
/proc/meminfo: memFree=346756/1022884 swapFree=0/0
[pid=17942] ppid=17941 vsize=9212 CPUtime=11.26
/proc/17942/stat : 17942 (aspuncud-full) S 17941 17942 1750 0 -1 4202496 767 141798 0 0 0 0 1048 78 20 0 1 0 119700058 9433088 365 18446744073709551615 4194304 5129932 140734592321360 140734592319424 140287784526942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17942/statm: 2303 365 303 229 0 63 0
[pid=17957] ppid=17942 vsize=153876 CPUtime=0.94
/proc/17957/stat : 17957 (unclasp) R 17942 17942 1750 0 -1 4202496 43236 0 0 0 80 14 0 0 20 0 1 0 119701230 157569024 37003 18446744073709551615 4194304 6012874 140733950200752 140733950199240 4613872 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17957/statm: 38469 37003 187 444 0 38017 0
[pid=17958] ppid=17942 vsize=22040 CPUtime=0.02
/proc/17958/stat : 17958 (parse.py) S 17942 17942 1750 0 -1 4202496 1320 0 0 0 1 1 0 0 20 0 1 0 119701230 22568960 1129 18446744073709551615 4194304 6642060 140734253252832 140734253251192 139849548076832 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/17958/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 12.22
Current children cumulated vsize (KiB) 185128

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

[startup+12.8005 s]
/proc/loadavg: 1.04 1.01 0.98 2/62 17958
/proc/meminfo: memFree=346756/1022884 swapFree=0/0
[pid=17942] ppid=17941 vsize=9212 CPUtime=11.26
/proc/17942/stat : 17942 (aspuncud-full) S 17941 17942 1750 0 -1 4202496 767 141798 0 0 0 0 1048 78 20 0 1 0 119700058 9433088 365 18446744073709551615 4194304 5129932 140734592321360 140734592319424 140287784526942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17942/statm: 2303 365 303 229 0 63 0
[pid=17957] ppid=17942 vsize=154236 CPUtime=1.05
/proc/17957/stat : 17957 (unclasp) R 17942 17942 1750 0 -1 4202496 43312 0 0 0 90 15 0 0 20 0 1 0 119701230 157937664 37079 18446744073709551615 4194304 6012874 140733950200752 140733950199336 4630037 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17957/statm: 38559 37079 188 444 0 38107 0
[pid=17958] ppid=17942 vsize=22040 CPUtime=0.02
/proc/17958/stat : 17958 (parse.py) S 17942 17942 1750 0 -1 4202496 1320 0 0 0 1 1 0 0 20 0 1 0 119701230 22568960 1129 18446744073709551615 4194304 6642060 140734253252832 140734253251192 139849548076832 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/17958/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 12.33
Current children cumulated vsize (KiB) 185488

[startup+13.2014 s]
/proc/loadavg: 1.04 1.01 0.98 2/62 17958
/proc/meminfo: memFree=388800/1022884 swapFree=0/0
[pid=17942] ppid=17941 vsize=9212 CPUtime=11.26
/proc/17942/stat : 17942 (aspuncud-full) S 17941 17942 1750 0 -1 4202496 767 141798 0 0 0 0 1048 78 20 0 1 0 119700058 9433088 365 18446744073709551615 4194304 5129932 140734592321360 140734592319424 140287784526942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17942/statm: 2303 365 303 229 0 63 0
[pid=17957] ppid=17942 vsize=144852 CPUtime=1.44
/proc/17957/stat : 17957 (unclasp) R 17942 17942 1750 0 -1 4202496 44080 0 0 0 125 19 0 0 20 0 1 0 119701230 148328448 9113 18446744073709551615 4194304 6012874 140733950200752 140733950200152 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17957/statm: 36213 9113 224 444 0 35761 0
[pid=17958] ppid=17942 vsize=22040 CPUtime=0.02
/proc/17958/stat : 17958 (parse.py) S 17942 17942 1750 0 -1 4202496 1320 0 0 0 1 1 0 0 20 0 1 0 119701230 22568960 1129 18446744073709551615 4194304 6642060 140734253252832 140734253251192 139849548076832 0 0 16777220 20994 0 0 0 17 0 0 0 1 0 0
/proc/17958/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 12.72
Current children cumulated vsize (KiB) 176104

Child status: 0
Real time (s): 13.2335
CPU time (s): 12.7808
CPU user time (s): 11.7607
CPU system time (s): 1.02006
CPU usage (%): 96.5788
Max. virtual memory (cumulated for all children) (KiB): 488388

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 11.7607
system time used= 1.02006
maximum resident set size= 417720
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 188242
page faults= 0
swaps= 0
block input operations= 41416
block output operations= 51136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 79
involuntary context switches= 1535

runsolver used 0.040002 second user time and 0.056003 second system time

The end