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/upgrade/difficult/rand752.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/upgrade/difficult/rand752.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/trendy-size/upgrade/difficult/rand752.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.11 1.05 0.99 2/59 18095
/proc/meminfo: memFree=433188/1022884 swapFree=0/0
[pid=18095] ppid=18094 vsize=3152 CPUtime=0
/proc/18095/stat : 18095 (runsolver) R 18094 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 119712504 3227648 32 18446744073709551615 134512640 134586868 4288912896 4288910944 4151600176 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/18095/statm: 788 32 0 19 0 73 0

[startup+0.179979 s]
/proc/loadavg: 1.11 1.05 0.99 2/59 18095
/proc/meminfo: memFree=433188/1022884 swapFree=0/0
[pid=18095] ppid=18094 vsize=9212 CPUtime=0.02
/proc/18095/stat : 18095 (aspuncud-full) S 18094 18095 1750 0 -1 4202496 697 2812 0 0 0 0 2 0 20 0 1 0 119712504 9433088 364 18446744073709551615 4194304 5129932 140734182324336 140734182322992 139896546092126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/18095/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200271 s]
/proc/loadavg: 1.11 1.05 0.99 2/59 18095
/proc/meminfo: memFree=433188/1022884 swapFree=0/0
[pid=18095] ppid=18094 vsize=9212 CPUtime=0.02
/proc/18095/stat : 18095 (aspuncud-full) S 18094 18095 1750 0 -1 4202496 697 2812 0 0 0 0 2 0 20 0 1 0 119712504 9433088 364 18446744073709551615 4194304 5129932 140734182324336 140734182322992 139896546092126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/18095/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300258 s]
/proc/loadavg: 1.11 1.05 0.99 2/59 18095
/proc/meminfo: memFree=433188/1022884 swapFree=0/0
[pid=18095] ppid=18094 vsize=9212 CPUtime=0.02
/proc/18095/stat : 18095 (aspuncud-full) S 18094 18095 1750 0 -1 4202496 697 2812 0 0 0 0 2 0 20 0 1 0 119712504 9433088 364 18446744073709551615 4194304 5129932 140734182324336 140734182322992 139896546092126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/18095/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700202 s]
/proc/loadavg: 1.11 1.05 0.99 2/59 18095
/proc/meminfo: memFree=433188/1022884 swapFree=0/0
[pid=18095] ppid=18094 vsize=9212 CPUtime=0.02
/proc/18095/stat : 18095 (aspuncud-full) S 18094 18095 1750 0 -1 4202496 697 2812 0 0 0 0 2 0 20 0 1 0 119712504 9433088 364 18446744073709551615 4194304 5129932 140734182324336 140734182322992 139896546092126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/18095/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 1.11 1.05 0.99 2/61 18108
/proc/meminfo: memFree=391748/1022884 swapFree=0/0
[pid=18095] ppid=18094 vsize=9212 CPUtime=0.02
/proc/18095/stat : 18095 (aspuncud-full) S 18094 18095 1750 0 -1 4202496 697 2812 0 0 0 0 2 0 20 0 1 0 119712504 9433088 364 18446744073709551615 4194304 5129932 140734182324336 140734182322992 139896546092126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/18095/statm: 2303 364 303 229 0 63 0
[pid=18108] ppid=18095 vsize=50676 CPUtime=1.42
/proc/18108/stat : 18108 (cudf2lp) R 18095 18095 1750 0 -1 4202496 14440 0 0 0 134 8 0 0 20 0 1 0 119712507 51892224 11040 18446744073709551615 4194304 5690517 140736382862528 140736382860168 4970678 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/18108/statm: 12669 11040 160 366 0 12300 0
Current children cumulated CPU time (s) 1.44
Current children cumulated vsize (KiB) 59888

[startup+3.10036 s]
/proc/loadavg: 1.10 1.05 0.99 2/61 18108
/proc/meminfo: memFree=362112/1022884 swapFree=0/0
[pid=18095] ppid=18094 vsize=9212 CPUtime=0.02
/proc/18095/stat : 18095 (aspuncud-full) S 18094 18095 1750 0 -1 4202496 697 2812 0 0 0 0 2 0 20 0 1 0 119712504 9433088 364 18446744073709551615 4194304 5129932 140734182324336 140734182322992 139896546092126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/18095/statm: 2303 364 303 229 0 63 0
[pid=18108] ppid=18095 vsize=93028 CPUtime=2.99
/proc/18108/stat : 18108 (cudf2lp) R 18095 18095 1750 0 -1 4202496 26858 0 0 0 283 16 0 0 20 0 1 0 119712507 95260672 20129 18446744073709551615 4194304 5690517 140736382862528 140736382860168 4360825 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/18108/statm: 23257 20129 160 366 0 22888 0
Current children cumulated CPU time (s) 3.01
Current children cumulated vsize (KiB) 102240

[startup+6.30025 s]
/proc/loadavg: 1.10 1.05 0.99 2/61 18109
/proc/meminfo: memFree=342644/1022884 swapFree=0/0
[pid=18095] ppid=18094 vsize=9212 CPUtime=4.42
/proc/18095/stat : 18095 (aspuncud-full) S 18094 18095 1750 0 -1 4202496 724 42135 0 0 0 0 416 26 20 0 1 0 119712504 9433088 364 18446744073709551615 4194304 5129932 140734182324336 140734182322992 139896546092126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/18095/statm: 2303 364 303 229 0 63 0
[pid=18109] ppid=18095 vsize=96468 CPUtime=1.77
/proc/18109/stat : 18109 (gringo) R 18095 18095 1750 0 -1 4202496 25034 0 0 0 168 9 0 0 20 0 1 0 119712956 98783232 20848 18446744073709551615 4194304 6531320 140734392073760 140734392070376 4359104 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/18109/statm: 24117 20848 276 571 0 23538 0
Current children cumulated CPU time (s) 6.19
Current children cumulated vsize (KiB) 105680

[startup+12.7003 s]
/proc/loadavg: 1.24 1.08 1.00 2/61 18109
/proc/meminfo: memFree=11208/1022884 swapFree=0/0
[pid=18095] ppid=18094 vsize=9212 CPUtime=4.42
/proc/18095/stat : 18095 (aspuncud-full) S 18094 18095 1750 0 -1 4202496 724 42135 0 0 0 0 416 26 20 0 1 0 119712504 9433088 364 18446744073709551615 4194304 5129932 140734182324336 140734182322992 139896546092126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/18095/statm: 2303 364 303 229 0 63 0
[pid=18109] ppid=18095 vsize=743132 CPUtime=7.7
/proc/18109/stat : 18109 (gringo) R 18095 18095 1750 0 -1 4202496 171825 0 0 0 716 54 0 0 20 0 1 0 119712956 760967168 155349 18446744073709551615 4194304 6531320 140734392073760 140734392070376 4358934 0 0 16781316 16386 0 0 0 17 0 0 0 19 0 0
/proc/18109/statm: 185783 155349 282 571 0 185204 0
Current children cumulated CPU time (s) 12.12
Current children cumulated vsize (KiB) 752344

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

[startup+12.8004 s]
/proc/loadavg: 1.24 1.08 1.00 2/61 18109
/proc/meminfo: memFree=11208/1022884 swapFree=0/0
[pid=18095] ppid=18094 vsize=9212 CPUtime=4.42
/proc/18095/stat : 18095 (aspuncud-full) S 18094 18095 1750 0 -1 4202496 724 42135 0 0 0 0 416 26 20 0 1 0 119712504 9433088 364 18446744073709551615 4194304 5129932 140734182324336 140734182322992 139896546092126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/18095/statm: 2303 364 303 229 0 63 0
[pid=18109] ppid=18095 vsize=750604 CPUtime=7.8
/proc/18109/stat : 18109 (gringo) R 18095 18095 1750 0 -1 4202496 173507 0 0 0 726 54 0 0 20 0 1 0 119712956 768618496 157031 18446744073709551615 4194304 6531320 140734392073760 140734392070376 5511045 0 0 16781316 16386 0 0 0 17 0 0 0 19 0 0
/proc/18109/statm: 187651 157031 282 571 0 187072 0
Current children cumulated CPU time (s) 12.22
Current children cumulated vsize (KiB) 759816

[startup+16.0003 s]
/proc/loadavg: 1.24 1.08 1.00 2/62 18111
/proc/meminfo: memFree=411232/1022884 swapFree=0/0
[pid=18095] ppid=18094 vsize=9212 CPUtime=13.33
/proc/18095/stat : 18095 (aspuncud-full) S 18094 18095 1750 0 -1 4202496 764 220988 0 0 0 0 1234 99 20 0 1 0 119712504 9433088 364 18446744073709551615 4194304 5129932 140734182324336 140734182322400 139896546092126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/18095/statm: 2303 364 303 229 0 63 0
[pid=18110] ppid=18095 vsize=228380 CPUtime=1.94
/proc/18110/stat : 18110 (unclasp) R 18095 18095 1750 0 -1 4202496 69207 0 1 0 170 24 0 0 20 0 1 0 119713896 233861120 56610 18446744073709551615 4194304 6012874 140736553380048 140736553379368 4548180 0 0 16781316 16386 0 0 0 17 0 0 0 9 0 0
/proc/18110/statm: 57095 56610 221 444 0 56643 0
[pid=18111] ppid=18095 vsize=22040 CPUtime=0.01
/proc/18111/stat : 18111 (parse.py) S 18095 18095 1750 0 -1 4202496 1306 0 13 0 1 0 0 0 20 0 1 0 119713896 22568960 1127 18446744073709551615 4194304 6642060 140733634516560 140733634514920 139945672869664 0 0 16777220 20994 0 0 0 17 0 0 0 15 0 0
/proc/18111/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 15.28
Current children cumulated vsize (KiB) 259632

[startup+19.2003 s]
/proc/loadavg: 1.22 1.08 1.00 2/62 18111
/proc/meminfo: memFree=423260/1022884 swapFree=0/0
[pid=18095] ppid=18094 vsize=9212 CPUtime=13.33
/proc/18095/stat : 18095 (aspuncud-full) S 18094 18095 1750 0 -1 4202496 764 220988 0 0 0 0 1234 99 20 0 1 0 119712504 9433088 364 18446744073709551615 4194304 5129932 140734182324336 140734182322400 139896546092126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/18095/statm: 2303 364 303 229 0 63 0
[pid=18110] ppid=18095 vsize=228380 CPUtime=5.11
/proc/18110/stat : 18110 (unclasp) R 18095 18095 1750 0 -1 4202496 69216 0 1 0 487 24 0 0 20 0 1 0 119713896 233861120 56619 18446744073709551615 4194304 6012874 140736553380048 140736553379368 4548180 0 0 16781316 16386 0 0 0 17 0 0 0 9 0 0
/proc/18110/statm: 57095 56619 230 444 0 56643 0
[pid=18111] ppid=18095 vsize=22368 CPUtime=0.01
/proc/18111/stat : 18111 (parse.py) S 18095 18095 1750 0 -1 4202496 1376 0 13 0 1 0 0 0 20 0 1 0 119713896 22904832 1197 18446744073709551615 4194304 6642060 140733634516560 140733634514808 139945672869664 0 0 16777220 20994 0 0 0 17 0 0 0 15 0 0
/proc/18111/statm: 5592 1197 508 598 0 678 0
Current children cumulated CPU time (s) 18.45
Current children cumulated vsize (KiB) 259960

[startup+20.8003 s]
/proc/loadavg: 1.22 1.08 1.00 2/62 18111
/proc/meminfo: memFree=423260/1022884 swapFree=0/0
[pid=18095] ppid=18094 vsize=9212 CPUtime=13.33
/proc/18095/stat : 18095 (aspuncud-full) S 18094 18095 1750 0 -1 4202496 764 220988 0 0 0 0 1234 99 20 0 1 0 119712504 9433088 364 18446744073709551615 4194304 5129932 140734182324336 140734182322400 139896546092126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/18095/statm: 2303 364 303 229 0 63 0
[pid=18110] ppid=18095 vsize=228380 CPUtime=6.7
/proc/18110/stat : 18110 (unclasp) R 18095 18095 1750 0 -1 4202496 69216 0 1 0 645 25 0 0 20 0 1 0 119713896 233861120 56619 18446744073709551615 4194304 6012874 140736553380048 140736553379368 4548913 0 0 16781316 16386 0 0 0 17 0 0 0 9 0 0
/proc/18110/statm: 57095 56619 230 444 0 56643 0
[pid=18111] ppid=18095 vsize=22368 CPUtime=0.01
/proc/18111/stat : 18111 (parse.py) S 18095 18095 1750 0 -1 4202496 1376 0 13 0 1 0 0 0 20 0 1 0 119713896 22904832 1197 18446744073709551615 4194304 6642060 140733634516560 140733634514808 139945672869664 0 0 16777220 20994 0 0 0 17 0 0 0 15 0 0
/proc/18111/statm: 5592 1197 508 598 0 678 0
Current children cumulated CPU time (s) 20.04
Current children cumulated vsize (KiB) 259960

[startup+21.2003 s]
/proc/loadavg: 1.22 1.08 1.00 2/62 18111
/proc/meminfo: memFree=423260/1022884 swapFree=0/0
[pid=18095] ppid=18094 vsize=9212 CPUtime=13.33
/proc/18095/stat : 18095 (aspuncud-full) S 18094 18095 1750 0 -1 4202496 764 220988 0 0 0 0 1234 99 20 0 1 0 119712504 9433088 364 18446744073709551615 4194304 5129932 140734182324336 140734182322400 139896546092126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/18095/statm: 2303 364 303 229 0 63 0
[pid=18110] ppid=18095 vsize=228380 CPUtime=7.1
/proc/18110/stat : 18110 (unclasp) R 18095 18095 1750 0 -1 4202496 69216 0 1 0 684 26 0 0 20 0 1 0 119713896 233861120 56619 18446744073709551615 4194304 6012874 140736553380048 140736553379368 4548180 0 0 16781316 16386 0 0 0 17 0 0 0 9 0 0
/proc/18110/statm: 57095 56619 230 444 0 56643 0
[pid=18111] ppid=18095 vsize=22368 CPUtime=0.01
/proc/18111/stat : 18111 (parse.py) S 18095 18095 1750 0 -1 4202496 1376 0 13 0 1 0 0 0 20 0 1 0 119713896 22904832 1197 18446744073709551615 4194304 6642060 140733634516560 140733634514808 139945672869664 0 0 16777220 20994 0 0 0 17 0 0 0 15 0 0
/proc/18111/statm: 5592 1197 508 598 0 678 0
Current children cumulated CPU time (s) 20.44
Current children cumulated vsize (KiB) 259960

[startup+21.4003 s]
/proc/loadavg: 1.22 1.08 1.00 2/62 18111
/proc/meminfo: memFree=423260/1022884 swapFree=0/0
[pid=18095] ppid=18094 vsize=9212 CPUtime=13.33
/proc/18095/stat : 18095 (aspuncud-full) S 18094 18095 1750 0 -1 4202496 764 220988 0 0 0 0 1234 99 20 0 1 0 119712504 9433088 364 18446744073709551615 4194304 5129932 140734182324336 140734182322400 139896546092126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/18095/statm: 2303 364 303 229 0 63 0
[pid=18110] ppid=18095 vsize=228380 CPUtime=7.3
/proc/18110/stat : 18110 (unclasp) R 18095 18095 1750 0 -1 4202496 69216 0 1 0 704 26 0 0 20 0 1 0 119713896 233861120 56619 18446744073709551615 4194304 6012874 140736553380048 140736553379368 4300161 0 0 16781316 16386 0 0 0 17 0 0 0 9 0 0
/proc/18110/statm: 57095 56619 230 444 0 56643 0
[pid=18111] ppid=18095 vsize=22368 CPUtime=0.01
/proc/18111/stat : 18111 (parse.py) S 18095 18095 1750 0 -1 4202496 1376 0 13 0 1 0 0 0 20 0 1 0 119713896 22904832 1197 18446744073709551615 4194304 6642060 140733634516560 140733634514728 139945672869664 0 0 16777220 20994 0 0 0 17 0 0 0 15 0 0
/proc/18111/statm: 5592 1197 508 598 0 678 0
Current children cumulated CPU time (s) 20.64
Current children cumulated vsize (KiB) 259960

[startup+21.5004 s]
/proc/loadavg: 1.22 1.08 1.00 2/62 18111
/proc/meminfo: memFree=423260/1022884 swapFree=0/0
[pid=18095] ppid=18094 vsize=9212 CPUtime=20.76
/proc/18095/stat : 18095 (aspuncud-full) S 18094 18095 1750 0 -1 4202496 798 291605 0 14 0 0 1944 132 20 0 1 0 119712504 9433088 364 18446744073709551615 4194304 5129932 140734182324336 140734182321888 139896546092126 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/18095/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 20.76
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 21.5246
CPU time (s): 20.7853
CPU user time (s): 19.4412
CPU system time (s): 1.34408
CPU usage (%): 96.5653
Max. virtual memory (cumulated for all children) (KiB): 784060

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 19.4412
system time used= 1.34408
maximum resident set size= 649492
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 292634
page faults= 15
swaps= 0
block input operations= 81664
block output operations= 81808
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 170
involuntary context switches= 2704

runsolver used 0.036002 second user time and 0.084005 second system time

The end