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/dist-upgrade/install/rand30.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/install/rand30.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/dist-upgrade/install/rand30.cudf.result -notuptodate(solution),-aligned(solution,source,sourceversion),-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 1.01 1.01 2/60 17927
/proc/meminfo: memFree=486388/1022884 swapFree=0/0
[pid=17927] ppid=17926 vsize=3152 CPUtime=0
/proc/17927/stat : 17927 (runsolver) R 17926 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 39741099 3227648 33 18446744073709551615 134512640 134586868 4288607936 4288605984 4151743536 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/17927/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.165203 s]
/proc/loadavg: 0.98 1.01 1.01 2/60 17927
/proc/meminfo: memFree=486388/1022884 swapFree=0/0
[pid=17927] ppid=17926 vsize=9212 CPUtime=0.03
/proc/17927/stat : 17927 (aspcud-full) S 17926 17927 32685 0 -1 4202496 735 3620 0 0 0 0 3 0 20 0 1 0 39741099 9433088 365 18446744073709551615 4194304 5129932 140734874796256 140734874794912 140057610179678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17927/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200361 s]
/proc/loadavg: 0.98 1.01 1.01 2/60 17927
/proc/meminfo: memFree=486388/1022884 swapFree=0/0
[pid=17927] ppid=17926 vsize=9212 CPUtime=0.03
/proc/17927/stat : 17927 (aspcud-full) S 17926 17927 32685 0 -1 4202496 735 3620 0 0 0 0 3 0 20 0 1 0 39741099 9433088 365 18446744073709551615 4194304 5129932 140734874796256 140734874794912 140057610179678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17927/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.30032 s]
/proc/loadavg: 0.98 1.01 1.01 2/60 17927
/proc/meminfo: memFree=486388/1022884 swapFree=0/0
[pid=17927] ppid=17926 vsize=9212 CPUtime=0.03
/proc/17927/stat : 17927 (aspcud-full) S 17926 17927 32685 0 -1 4202496 735 3620 0 0 0 0 3 0 20 0 1 0 39741099 9433088 365 18446744073709551615 4194304 5129932 140734874796256 140734874794912 140057610179678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17927/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700215 s]
/proc/loadavg: 0.98 1.01 1.01 2/60 17927
/proc/meminfo: memFree=486388/1022884 swapFree=0/0
[pid=17927] ppid=17926 vsize=9212 CPUtime=0.03
/proc/17927/stat : 17927 (aspcud-full) S 17926 17927 32685 0 -1 4202496 735 3620 0 0 0 0 3 0 20 0 1 0 39741099 9433088 365 18446744073709551615 4194304 5129932 140734874796256 140734874794912 140057610179678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17927/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50029 s]
/proc/loadavg: 0.98 1.01 1.01 2/62 17943
/proc/meminfo: memFree=447676/1022884 swapFree=0/0
[pid=17927] ppid=17926 vsize=9212 CPUtime=0.03
/proc/17927/stat : 17927 (aspcud-full) S 17926 17927 32685 0 -1 4202496 735 3620 0 0 0 0 3 0 20 0 1 0 39741099 9433088 365 18446744073709551615 4194304 5129932 140734874796256 140734874794912 140057610179678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17927/statm: 2303 365 303 229 0 63 0
[pid=17943] ppid=17927 vsize=53756 CPUtime=1.26
/proc/17943/stat : 17943 (cudf2lp) R 17927 17927 32685 0 -1 4202496 15058 0 0 0 122 4 0 0 20 0 1 0 39741102 55046144 11660 18446744073709551615 4194304 5690517 140736286816576 140736286814216 4348987 0 0 16781316 0 0 0 0 17 0 0 0 20 0 0
/proc/17943/statm: 13439 11660 160 366 0 13070 0
Current children cumulated CPU time (s) 1.29
Current children cumulated vsize (KiB) 62968

[startup+3.10033 s]
/proc/loadavg: 0.98 1.01 1.01 1/62 17943
/proc/meminfo: memFree=415684/1022884 swapFree=0/0
[pid=17927] ppid=17926 vsize=9212 CPUtime=0.03
/proc/17927/stat : 17927 (aspcud-full) S 17926 17927 32685 0 -1 4202496 735 3620 0 0 0 0 3 0 20 0 1 0 39741099 9433088 365 18446744073709551615 4194304 5129932 140734874796256 140734874794912 140057610179678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17927/statm: 2303 365 303 229 0 63 0
[pid=17943] ppid=17927 vsize=99144 CPUtime=2.36
/proc/17943/stat : 17943 (cudf2lp) R 17927 17927 32685 0 -1 4202496 27941 0 0 0 225 11 0 0 20 0 1 0 39741102 101523456 21214 18446744073709551615 4194304 5690517 140736286816576 140736286814216 4362177 0 0 16781316 0 0 0 0 17 0 0 0 69 0 0
/proc/17943/statm: 24786 21214 160 366 0 24417 0
Current children cumulated CPU time (s) 2.39
Current children cumulated vsize (KiB) 108356
heavy processes:

[startup+6.30027 s]
/proc/loadavg: 0.98 1.01 1.01 2/62 17944
/proc/meminfo: memFree=416900/1022884 swapFree=0/0
[pid=17927] ppid=17926 vsize=9212 CPUtime=4.16
/proc/17927/stat : 17927 (aspcud-full) S 17926 17927 32685 0 -1 4202496 761 44896 0 0 0 0 390 26 20 0 1 0 39741099 9433088 365 18446744073709551615 4194304 5129932 140734874796256 140734874794912 140057610179678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17927/statm: 2303 365 303 229 0 63 0
[pid=17944] ppid=17927 vsize=54948 CPUtime=1.23
/proc/17944/stat : 17944 (gringo) R 17927 17927 32685 0 -1 4202496 15820 0 0 0 117 6 0 0 20 0 1 0 39741605 56266752 11662 18446744073709551615 4194304 6531320 140733830771408 140733830766952 4360270 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/17944/statm: 13737 11662 259 571 0 13158 0
Current children cumulated CPU time (s) 5.39
Current children cumulated vsize (KiB) 64160

[startup+12.7003 s]
/proc/loadavg: 0.98 1.01 1.01 2/63 17949
/proc/meminfo: memFree=458884/1022884 swapFree=0/0
[pid=17927] ppid=17926 vsize=9212 CPUtime=10.83
/proc/17927/stat : 17927 (aspcud-full) S 17926 17927 32685 0 -1 4202496 801 183424 0 0 0 0 1010 73 20 0 1 0 39741099 9433088 365 18446744073709551615 4194304 5129932 140734874796256 140734874794320 140057610179678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17927/statm: 2303 365 303 229 0 63 0
[pid=17948] ppid=17927 vsize=168324 CPUtime=0.72
/proc/17948/stat : 17948 (clasp) R 17927 17927 32685 0 -1 4202496 46696 0 1 0 59 13 0 0 20 0 1 0 39742288 172363776 40461 18446744073709551615 4194304 6238623 140735599079104 140735599076664 4778634 0 0 16781316 18946 0 0 0 17 0 0 0 5 0 0
/proc/17948/statm: 42081 40461 211 500 0 41578 0
[pid=17949] ppid=17927 vsize=22040 CPUtime=0.02
/proc/17949/stat : 17949 (parse.py) S 17927 17927 32685 0 -1 4202496 1307 0 10 0 2 0 0 0 20 0 1 0 39742288 22568960 1127 18446744073709551615 4194304 6642060 140735196719408 140735196717768 139885456828192 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/17949/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 11.57
Current children cumulated vsize (KiB) 199576

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

[startup+12.8004 s]
/proc/loadavg: 0.98 1.01 1.01 2/63 17949
/proc/meminfo: memFree=458884/1022884 swapFree=0/0
[pid=17927] ppid=17926 vsize=9212 CPUtime=10.83
/proc/17927/stat : 17927 (aspcud-full) S 17926 17927 32685 0 -1 4202496 801 183424 0 0 0 0 1010 73 20 0 1 0 39741099 9433088 365 18446744073709551615 4194304 5129932 140734874796256 140734874794320 140057610179678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17927/statm: 2303 365 303 229 0 63 0
[pid=17948] ppid=17927 vsize=169732 CPUtime=0.82
/proc/17948/stat : 17948 (clasp) R 17927 17927 32685 0 -1 4202496 47010 0 1 0 69 13 0 0 20 0 1 0 39742288 173805568 40775 18446744073709551615 4194304 6238623 140735599079104 140735599076440 4494854 0 0 16781316 18946 0 0 0 17 0 0 0 5 0 0
/proc/17948/statm: 42433 40775 215 500 0 41930 0
[pid=17949] ppid=17927 vsize=22040 CPUtime=0.02
/proc/17949/stat : 17949 (parse.py) S 17927 17927 32685 0 -1 4202496 1307 0 10 0 2 0 0 0 20 0 1 0 39742288 22568960 1127 18446744073709551615 4194304 6642060 140735196719408 140735196717768 139885456828192 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/17949/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 11.67
Current children cumulated vsize (KiB) 200984

[startup+14.4034 s]
/proc/loadavg: 0.98 1.01 1.01 2/63 17949
/proc/meminfo: memFree=323980/1022884 swapFree=0/0
[pid=17927] ppid=17926 vsize=9212 CPUtime=10.83
/proc/17927/stat : 17927 (aspcud-full) S 17926 17927 32685 0 -1 4202496 801 183424 0 0 0 0 1010 73 20 0 1 0 39741099 9433088 365 18446744073709551615 4194304 5129932 140734874796256 140734874794320 140057610179678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17927/statm: 2303 365 303 229 0 63 0
[pid=17948] ppid=17927 vsize=166280 CPUtime=2.42
/proc/17948/stat : 17948 (clasp) R 17927 17927 32685 0 -1 4202496 49294 0 1 0 228 14 0 0 20 0 1 0 39742288 170270720 40731 18446744073709551615 4194304 6238623 140735599079104 140735599076128 4669491 0 0 16781316 18946 0 0 0 17 0 0 0 5 0 0
/proc/17948/statm: 41570 40731 264 500 0 41067 0
[pid=17949] ppid=17927 vsize=22040 CPUtime=0.02
/proc/17949/stat : 17949 (parse.py) S 17927 17927 32685 0 -1 4202496 1307 0 10 0 2 0 0 0 20 0 1 0 39742288 22568960 1127 18446744073709551615 4194304 6642060 140735196719408 140735196717768 139885456828192 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/17949/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 13.27
Current children cumulated vsize (KiB) 197532

[startup+14.8003 s]
/proc/loadavg: 0.98 1.01 1.01 2/63 17949
/proc/meminfo: memFree=323980/1022884 swapFree=0/0
[pid=17927] ppid=17926 vsize=9212 CPUtime=10.83
/proc/17927/stat : 17927 (aspcud-full) S 17926 17927 32685 0 -1 4202496 801 183424 0 0 0 0 1010 73 20 0 1 0 39741099 9433088 365 18446744073709551615 4194304 5129932 140734874796256 140734874794320 140057610179678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17927/statm: 2303 365 303 229 0 63 0
[pid=17948] ppid=17927 vsize=166280 CPUtime=2.81
/proc/17948/stat : 17948 (clasp) R 17927 17927 32685 0 -1 4202496 49298 0 1 0 267 14 0 0 20 0 1 0 39742288 170270720 40735 18446744073709551615 4194304 6238623 140735599079104 140735599076128 4409880 0 0 16781316 18946 0 0 0 17 0 0 0 5 0 0
/proc/17948/statm: 41570 40735 264 500 0 41067 0
[pid=17949] ppid=17927 vsize=22040 CPUtime=0.02
/proc/17949/stat : 17949 (parse.py) S 17927 17927 32685 0 -1 4202496 1307 0 10 0 2 0 0 0 20 0 1 0 39742288 22568960 1127 18446744073709551615 4194304 6642060 140735196719408 140735196717768 139885456828192 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/17949/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 13.66
Current children cumulated vsize (KiB) 197532

[startup+15.2005 s]
/proc/loadavg: 0.98 1.01 1.01 2/63 17949
/proc/meminfo: memFree=323980/1022884 swapFree=0/0
[pid=17927] ppid=17926 vsize=9212 CPUtime=14
/proc/17927/stat : 17927 (aspcud-full) S 17926 17927 32685 0 -1 4202496 836 234061 0 16 0 0 1307 93 20 0 1 0 39741099 9433088 365 18446744073709551615 4194304 5129932 140734874796256 140734874793808 140057610179678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/17927/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 14
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 15.2509
CPU time (s): 14.0409
CPU user time (s): 13.0768
CPU system time (s): 0.96406
CPU usage (%): 92.0661
Max. virtual memory (cumulated for all children) (KiB): 597704

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.0768
system time used= 0.96406
maximum resident set size= 480108
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 235131
page faults= 17
swaps= 0
block input operations= 70416
block output operations= 66816
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 251
involuntary context switches= 363

runsolver used 0.040002 second user time and 0.052003 second system time

The end