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/d0cc7514-c730-11df-a040-00163e3d3b7c.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/real/d0cc7514-c730-11df-a040-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/trendy-size/real/d0cc7514-c730-11df-a040-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.98 0.97 0.95 2/60 23980
/proc/meminfo: memFree=627824/1022884 swapFree=0/0
[pid=23980] ppid=23979 vsize=3152 CPUtime=0
/proc/23980/stat : 23980 (runsolver) R 23979 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 41469732 3227648 33 18446744073709551615 134512640 134586868 4290781312 4290779360 4151555120 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/23980/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.183306 s]
/proc/loadavg: 0.98 0.97 0.95 2/60 23980
/proc/meminfo: memFree=627824/1022884 swapFree=0/0
[pid=23980] ppid=23979 vsize=9212 CPUtime=0.03
/proc/23980/stat : 23980 (aspuncud-full) S 23979 23980 32685 0 -1 4202496 697 2809 0 0 0 0 2 1 20 0 1 0 41469732 9433088 365 18446744073709551615 4194304 5129932 140737151396624 140737151395280 139913006273630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23980/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200329 s]
/proc/loadavg: 0.98 0.97 0.95 2/60 23980
/proc/meminfo: memFree=627824/1022884 swapFree=0/0
[pid=23980] ppid=23979 vsize=9212 CPUtime=0.03
/proc/23980/stat : 23980 (aspuncud-full) S 23979 23980 32685 0 -1 4202496 697 2809 0 0 0 0 2 1 20 0 1 0 41469732 9433088 365 18446744073709551615 4194304 5129932 140737151396624 140737151395280 139913006273630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23980/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300323 s]
/proc/loadavg: 0.98 0.97 0.95 2/60 23980
/proc/meminfo: memFree=627824/1022884 swapFree=0/0
[pid=23980] ppid=23979 vsize=9212 CPUtime=0.03
/proc/23980/stat : 23980 (aspuncud-full) S 23979 23980 32685 0 -1 4202496 697 2809 0 0 0 0 2 1 20 0 1 0 41469732 9433088 365 18446744073709551615 4194304 5129932 140737151396624 140737151395280 139913006273630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23980/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700241 s]
/proc/loadavg: 0.98 0.97 0.95 2/60 23980
/proc/meminfo: memFree=627824/1022884 swapFree=0/0
[pid=23980] ppid=23979 vsize=9212 CPUtime=0.03
/proc/23980/stat : 23980 (aspuncud-full) S 23979 23980 32685 0 -1 4202496 697 2809 0 0 0 0 2 1 20 0 1 0 41469732 9433088 365 18446744073709551615 4194304 5129932 140737151396624 140737151395280 139913006273630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23980/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 0.98 0.97 0.95 2/62 23993
/proc/meminfo: memFree=592832/1022884 swapFree=0/0
[pid=23980] ppid=23979 vsize=9212 CPUtime=0.03
/proc/23980/stat : 23980 (aspuncud-full) S 23979 23980 32685 0 -1 4202496 697 2809 0 0 0 0 2 1 20 0 1 0 41469732 9433088 365 18446744073709551615 4194304 5129932 140737151396624 140737151395280 139913006273630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23980/statm: 2303 365 303 229 0 63 0
[pid=23993] ppid=23980 vsize=56180 CPUtime=1.43
/proc/23993/stat : 23993 (cudf2lp) R 23980 23980 32685 0 -1 4202496 13590 0 0 0 138 5 0 0 20 0 1 0 41469735 57528320 11857 18446744073709551615 4194304 5690517 140735068592304 140735068588504 4370468 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/23993/statm: 14045 11857 160 366 0 13676 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 65392

[startup+3.10033 s]
/proc/loadavg: 0.98 0.97 0.95 2/62 23993
/proc/meminfo: memFree=560220/1022884 swapFree=0/0
[pid=23980] ppid=23979 vsize=9212 CPUtime=0.03
/proc/23980/stat : 23980 (aspuncud-full) S 23979 23980 32685 0 -1 4202496 697 2809 0 0 0 0 2 1 20 0 1 0 41469732 9433088 365 18446744073709551615 4194304 5129932 140737151396624 140737151395280 139913006273630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23980/statm: 2303 365 303 229 0 63 0
[pid=23993] ppid=23980 vsize=78192 CPUtime=3.03
/proc/23993/stat : 23993 (cudf2lp) R 23980 23980 32685 0 -1 4202496 25439 0 0 0 288 15 0 0 20 0 1 0 41469735 80068608 19274 18446744073709551615 4194304 5690517 140735068592304 140735068589656 4934592 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/23993/statm: 19548 19274 174 366 0 19179 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 87404

[startup+6.30033 s]
/proc/loadavg: 0.98 0.97 0.95 2/62 23994
/proc/meminfo: memFree=531328/1022884 swapFree=0/0
[pid=23980] ppid=23979 vsize=9212 CPUtime=3.31
/proc/23980/stat : 23980 (aspuncud-full) S 23979 23980 32685 0 -1 4202496 724 28250 0 0 0 0 312 19 20 0 1 0 41469732 9433088 365 18446744073709551615 4194304 5129932 140737151396624 140737151395280 139913006273630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23980/statm: 2303 365 303 229 0 63 0
[pid=23994] ppid=23980 vsize=119204 CPUtime=2.93
/proc/23994/stat : 23994 (gringo) R 23980 23980 32685 0 -1 4202496 31302 0 0 0 279 14 0 0 20 0 1 0 41470066 122064896 27117 18446744073709551615 4194304 6531320 140735836528720 140735836525336 5511034 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23994/statm: 29801 27117 280 571 0 29222 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 128416

[startup+12.7002 s]
/proc/loadavg: 0.98 0.97 0.95 2/62 23994
/proc/meminfo: memFree=120268/1022884 swapFree=0/0
[pid=23980] ppid=23979 vsize=9212 CPUtime=12.26
/proc/23980/stat : 23980 (aspuncud-full) S 23979 23980 32685 0 -1 4202496 763 168460 0 0 0 0 1134 92 20 0 1 0 41469732 9433088 365 18446744073709551615 4194304 5129932 140737151396624 140737151394688 139913006273630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23980/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 12.26
Current children cumulated vsize (KiB) 9212

[startup+25.5003 s]
/proc/loadavg: 0.99 0.97 0.95 2/63 23996
/proc/meminfo: memFree=401492/1022884 swapFree=0/0
[pid=23980] ppid=23979 vsize=9212 CPUtime=12.26
/proc/23980/stat : 23980 (aspuncud-full) S 23979 23980 32685 0 -1 4202496 763 168460 0 0 0 0 1134 92 20 0 1 0 41469732 9433088 365 18446744073709551615 4194304 5129932 140737151396624 140737151394688 139913006273630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23980/statm: 2303 365 303 229 0 63 0
[pid=23995] ppid=23980 vsize=174716 CPUtime=13.04
/proc/23995/stat : 23995 (unclasp) R 23980 23980 32685 0 -1 4202496 51686 0 0 0 1280 24 0 0 20 0 1 0 41470968 178909184 42958 18446744073709551615 4194304 6012874 140734899202560 140734899201880 4535968 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23995/statm: 43679 42958 230 444 0 43227 0
[pid=23996] ppid=23980 vsize=22368 CPUtime=0.02
/proc/23996/stat : 23996 (parse.py) S 23980 23980 32685 0 -1 4202496 1398 0 0 0 1 1 0 0 20 0 1 0 41470968 22904832 1208 18446744073709551615 4194304 6642060 140737295615936 140737295613896 140249835755296 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23996/statm: 5592 1208 508 598 0 678 0
Current children cumulated CPU time (s) 25.32
Current children cumulated vsize (KiB) 206296

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

[startup+25.6004 s]
/proc/loadavg: 0.99 0.97 0.95 2/63 23996
/proc/meminfo: memFree=401492/1022884 swapFree=0/0
[pid=23980] ppid=23979 vsize=9212 CPUtime=12.26
/proc/23980/stat : 23980 (aspuncud-full) S 23979 23980 32685 0 -1 4202496 763 168460 0 0 0 0 1134 92 20 0 1 0 41469732 9433088 365 18446744073709551615 4194304 5129932 140737151396624 140737151394688 139913006273630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23980/statm: 2303 365 303 229 0 63 0
[pid=23995] ppid=23980 vsize=174716 CPUtime=13.14
/proc/23995/stat : 23995 (unclasp) R 23980 23980 32685 0 -1 4202496 51686 0 0 0 1290 24 0 0 20 0 1 0 41470968 178909184 42958 18446744073709551615 4194304 6012874 140734899202560 140734899201880 4548102 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23995/statm: 43679 42958 230 444 0 43227 0
[pid=23996] ppid=23980 vsize=22368 CPUtime=0.02
/proc/23996/stat : 23996 (parse.py) S 23980 23980 32685 0 -1 4202496 1398 0 0 0 1 1 0 0 20 0 1 0 41470968 22904832 1208 18446744073709551615 4194304 6642060 140737295615936 140737295613896 140249835755296 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23996/statm: 5592 1208 508 598 0 678 0
Current children cumulated CPU time (s) 25.42
Current children cumulated vsize (KiB) 206296

[startup+27.2003 s]
/proc/loadavg: 0.99 0.97 0.95 2/63 23996
/proc/meminfo: memFree=401492/1022884 swapFree=0/0
[pid=23980] ppid=23979 vsize=9212 CPUtime=12.26
/proc/23980/stat : 23980 (aspuncud-full) S 23979 23980 32685 0 -1 4202496 763 168460 0 0 0 0 1134 92 20 0 1 0 41469732 9433088 365 18446744073709551615 4194304 5129932 140737151396624 140737151394688 139913006273630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23980/statm: 2303 365 303 229 0 63 0
[pid=23995] ppid=23980 vsize=174716 CPUtime=14.73
/proc/23995/stat : 23995 (unclasp) R 23980 23980 32685 0 -1 4202496 51693 0 0 0 1449 24 0 0 20 0 1 0 41470968 178909184 42965 18446744073709551615 4194304 6012874 140734899202560 140734899201880 4532216 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23995/statm: 43679 42965 230 444 0 43227 0
[pid=23996] ppid=23980 vsize=22368 CPUtime=0.02
/proc/23996/stat : 23996 (parse.py) S 23980 23980 32685 0 -1 4202496 1398 0 0 0 1 1 0 0 20 0 1 0 41470968 22904832 1208 18446744073709551615 4194304 6642060 140737295615936 140737295613896 140249835755296 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23996/statm: 5592 1208 508 598 0 678 0
Current children cumulated CPU time (s) 27.01
Current children cumulated vsize (KiB) 206296

[startup+28.8004 s]
/proc/loadavg: 0.99 0.97 0.95 2/63 23996
/proc/meminfo: memFree=401368/1022884 swapFree=0/0
[pid=23980] ppid=23979 vsize=9212 CPUtime=12.26
/proc/23980/stat : 23980 (aspuncud-full) S 23979 23980 32685 0 -1 4202496 763 168460 0 0 0 0 1134 92 20 0 1 0 41469732 9433088 365 18446744073709551615 4194304 5129932 140737151396624 140737151394688 139913006273630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23980/statm: 2303 365 303 229 0 63 0
[pid=23995] ppid=23980 vsize=174716 CPUtime=16.31
/proc/23995/stat : 23995 (unclasp) R 23980 23980 32685 0 -1 4202496 51697 0 0 0 1607 24 0 0 20 0 1 0 41470968 178909184 42969 18446744073709551615 4194304 6012874 140734899202560 140734899201880 4548507 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23995/statm: 43679 42969 230 444 0 43227 0
[pid=23996] ppid=23980 vsize=22368 CPUtime=0.02
/proc/23996/stat : 23996 (parse.py) S 23980 23980 32685 0 -1 4202496 1398 0 0 0 1 1 0 0 20 0 1 0 41470968 22904832 1208 18446744073709551615 4194304 6642060 140737295615936 140737295613896 140249835755296 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23996/statm: 5592 1208 508 598 0 678 0
Current children cumulated CPU time (s) 28.59
Current children cumulated vsize (KiB) 206296

[startup+29.2004 s]
/proc/loadavg: 0.99 0.97 0.95 2/63 23996
/proc/meminfo: memFree=401368/1022884 swapFree=0/0
[pid=23980] ppid=23979 vsize=9212 CPUtime=12.26
/proc/23980/stat : 23980 (aspuncud-full) S 23979 23980 32685 0 -1 4202496 763 168460 0 0 0 0 1134 92 20 0 1 0 41469732 9433088 365 18446744073709551615 4194304 5129932 140737151396624 140737151394688 139913006273630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23980/statm: 2303 365 303 229 0 63 0
[pid=23995] ppid=23980 vsize=174716 CPUtime=16.71
/proc/23995/stat : 23995 (unclasp) R 23980 23980 32685 0 -1 4202496 51697 0 0 0 1647 24 0 0 20 0 1 0 41470968 178909184 42969 18446744073709551615 4194304 6012874 140734899202560 140734899201880 4855815 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23995/statm: 43679 42969 230 444 0 43227 0
[pid=23996] ppid=23980 vsize=22368 CPUtime=0.02
/proc/23996/stat : 23996 (parse.py) S 23980 23980 32685 0 -1 4202496 1398 0 0 0 1 1 0 0 20 0 1 0 41470968 22904832 1208 18446744073709551615 4194304 6642060 140737295615936 140737295613896 140249835755296 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23996/statm: 5592 1208 508 598 0 678 0
Current children cumulated CPU time (s) 28.99
Current children cumulated vsize (KiB) 206296

[startup+29.4014 s]
/proc/loadavg: 0.99 0.97 0.95 2/63 23996
/proc/meminfo: memFree=401368/1022884 swapFree=0/0
[pid=23980] ppid=23979 vsize=9212 CPUtime=12.26
/proc/23980/stat : 23980 (aspuncud-full) S 23979 23980 32685 0 -1 4202496 763 168460 0 0 0 0 1134 92 20 0 1 0 41469732 9433088 365 18446744073709551615 4194304 5129932 140737151396624 140737151394688 139913006273630 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/23980/statm: 2303 365 303 229 0 63 0
[pid=23995] ppid=23980 vsize=174716 CPUtime=16.91
/proc/23995/stat : 23995 (unclasp) R 23980 23980 32685 0 -1 4202496 51704 0 0 0 1661 30 0 0 20 0 1 0 41470968 178909184 4064 18446744073709551615 4194304 6012874 140734899202560 140734899201960 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/23995/statm: 43679 4064 237 444 0 43227 0
[pid=23996] ppid=23980 vsize=22524 CPUtime=0.02
/proc/23996/stat : 23996 (parse.py) S 23980 23980 32685 0 -1 4202496 1410 0 0 0 1 1 0 0 20 0 1 0 41470968 23064576 1220 18446744073709551615 4194304 6642060 140737295615936 140737295613976 140249835755296 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/23996/statm: 5631 1220 508 598 0 717 0
Current children cumulated CPU time (s) 29.19
Current children cumulated vsize (KiB) 206452

Child status: 0
Real time (s): 29.4339
CPU time (s): 29.2618
CPU user time (s): 27.9897
CPU system time (s): 1.27208
CPU usage (%): 99.4153
Max. virtual memory (cumulated for all children) (KiB): 598340

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 27.9897
system time used= 1.27208
maximum resident set size= 494924
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 222623
page faults= 0
swaps= 0
block input operations= 43848
block output operations= 59000
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 203
involuntary context switches= 615

runsolver used 0.064004 second user time and 0.120007 second system time

The end