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: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012091434/aspcud-1.3/rand95e48b.cudf.difficult.log.runsolver ./aspcud-1.3 /home/misc2010/data/2010/difficult//rand95e48b.cudf /home/misc2010/tmp/201012091434/aspcud-1.3/rand95e48b.cudf.difficult.result -changed,-removed,-unmet_recommends,-new 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 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.04 1.00 5/41 31401
/proc/meminfo: memFree=378920/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2584 CPUtime=0
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 375 0 0 0 0 0 0 0 18 0 1 0 900449518 2646016 281 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/31398/statm: 646 281 237 194 0 32 0
[pid=31399] ppid=31398 vsize=2584 CPUtime=0
/proc/31399/stat : 31399 (aspcud-1.3) S 31398 31398 25521 34816 25544 4202560 113 0 0 0 0 0 0 0 18 0 1 0 900449518 2646016 128 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/31399/statm: 646 128 83 194 0 32 0
[pid=31400] ppid=31399 vsize=2584 CPUtime=0
/proc/31400/stat : 31400 (aspcud-1.3) R 31399 31398 25521 34816 25544 4202560 126 0 0 0 0 0 0 0 25 0 1 0 900449518 2646016 148 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/31400/statm: 646 148 103 194 0 32 0
[pid=31401] ppid=31400 vsize=2584 CPUtime=0
/proc/31401/stat : 31401 (aspcud-1.3) R 31400 31398 25521 34816 25544 4202560 0 0 0 0 0 0 0 0 25 0 1 0 900449518 2646016 45 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/31401/statm: 646 45 0 194 0 32 0

[startup+0.183182 s]
/proc/loadavg: 1.06 1.04 1.00 5/41 31401
/proc/meminfo: memFree=378920/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=0
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 1506 0 0 0 0 0 0 25 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.213194 s]
/proc/loadavg: 1.06 1.04 1.00 5/41 31401
/proc/meminfo: memFree=378920/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=0
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 1506 0 0 0 0 0 0 25 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.313204 s]
/proc/loadavg: 1.06 1.04 1.00 5/41 31401
/proc/meminfo: memFree=378920/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=0
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 1506 0 0 0 0 0 0 25 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+0.713283 s]
/proc/loadavg: 1.06 1.04 1.00 5/41 31401
/proc/meminfo: memFree=378920/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=0
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 1506 0 0 0 0 0 0 25 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2592

[startup+1.51342 s]
/proc/loadavg: 1.06 1.04 1.00 2/42 31409
/proc/meminfo: memFree=339600/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=0.87
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 10726 0 0 0 0 82 5 18 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
[pid=31407] ppid=31398 vsize=14240 CPUtime=0.07
/proc/31407/stat : 31407 (clasp) S 31398 31398 25521 34816 25544 4202496 3763 0 0 0 7 0 0 0 18 0 1 0 900449519 14581760 3246 1283457024 134512640 136223643 4289824016 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/31407/statm: 3560 3246 174 418 0 3140 0
[pid=31408] ppid=31398 vsize=25140 CPUtime=0.55
/proc/31408/stat : 31408 (gringo) R 31398 31398 25521 34816 25544 4202496 6192 0 0 0 53 2 0 0 19 0 1 0 900449519 25743360 4661 1283457024 134512640 136959103 4293910896 18446744073709551615 134740718 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31408/statm: 6285 4661 256 598 0 5684 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 41972

[startup+3.1137 s]
/proc/loadavg: 1.06 1.04 1.00 2/40 31409
/proc/meminfo: memFree=358604/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=1.55
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 17770 0 0 0 0 147 8 15 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
[pid=31407] ppid=31398 vsize=22976 CPUtime=1.54
/proc/31407/stat : 31407 (clasp) R 31398 31398 25521 34816 25544 4202496 6161 0 0 0 152 2 0 0 20 0 1 0 900449519 23527424 5221 1283457024 134512640 136223643 4289824016 18446744073709551615 134929015 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31407/statm: 5744 5221 225 418 0 5324 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 25568

[startup+6.31423 s]
/proc/loadavg: 1.05 1.04 1.00 2/40 31409
/proc/meminfo: memFree=358604/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=1.55
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 17770 0 0 0 0 147 8 15 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
[pid=31407] ppid=31398 vsize=22976 CPUtime=4.73
/proc/31407/stat : 31407 (clasp) R 31398 31398 25521 34816 25544 4202496 6168 0 0 0 471 2 0 0 25 0 1 0 900449519 23527424 5228 1283457024 134512640 136223643 4289824016 18446744073709551615 134711968 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31407/statm: 5744 5228 225 418 0 5324 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 25568

[startup+12.7157 s]
/proc/loadavg: 1.05 1.04 1.00 2/40 31409
/proc/meminfo: memFree=358604/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=1.55
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 17770 0 0 0 0 147 8 15 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
[pid=31407] ppid=31398 vsize=22976 CPUtime=11.13
/proc/31407/stat : 31407 (clasp) R 31398 31398 25521 34816 25544 4202496 6168 0 0 0 1110 3 0 0 25 0 1 0 900449519 23527424 5228 1283457024 134512640 136223643 4289824016 18446744073709551615 134929006 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31407/statm: 5744 5228 225 418 0 5324 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 25568

[startup+25.511 s]
/proc/loadavg: 1.04 1.03 1.00 2/40 31409
/proc/meminfo: memFree=358604/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=1.55
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 17770 0 0 0 0 147 8 15 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
[pid=31407] ppid=31398 vsize=22976 CPUtime=23.9
/proc/31407/stat : 31407 (clasp) R 31398 31398 25521 34816 25544 4202496 6168 0 0 0 2387 3 0 0 25 0 1 0 900449519 23527424 5228 1283457024 134512640 136223643 4289824016 18446744073709551615 134704859 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31407/statm: 5744 5228 225 418 0 5324 0
Current children cumulated CPU time (s) 25.45
Current children cumulated vsize (KiB) 25568

[startup+51.1063 s]
/proc/loadavg: 1.02 1.03 1.00 2/40 31409
/proc/meminfo: memFree=358604/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=1.55
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 17770 0 0 0 0 147 8 15 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
[pid=31407] ppid=31398 vsize=22976 CPUtime=49.46
/proc/31407/stat : 31407 (clasp) R 31398 31398 25521 34816 25544 4202496 6168 0 0 0 4943 3 0 0 25 0 1 0 900449519 23527424 5228 1283457024 134512640 136223643 4289824016 18446744073709551615 134713041 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31407/statm: 5744 5228 225 418 0 5324 0
Current children cumulated CPU time (s) 51.01
Current children cumulated vsize (KiB) 25568

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

[startup+51.2064 s]
/proc/loadavg: 1.02 1.03 1.00 2/40 31409
/proc/meminfo: memFree=358604/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=1.55
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 17770 0 0 0 0 147 8 15 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
[pid=31407] ppid=31398 vsize=22976 CPUtime=49.56
/proc/31407/stat : 31407 (clasp) R 31398 31398 25521 34816 25544 4202496 6168 0 0 0 4953 3 0 0 25 0 1 0 900449519 23527424 5228 1283457024 134512640 136223643 4289824016 18446744073709551615 134711200 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31407/statm: 5744 5228 225 418 0 5324 0
Current children cumulated CPU time (s) 51.11
Current children cumulated vsize (KiB) 25568

[startup+57.6081 s]
/proc/loadavg: 1.02 1.03 1.00 2/40 31409
/proc/meminfo: memFree=358604/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=1.55
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 17770 0 0 0 0 147 8 15 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
[pid=31407] ppid=31398 vsize=22976 CPUtime=55.95
/proc/31407/stat : 31407 (clasp) R 31398 31398 25521 34816 25544 4202496 6168 0 0 0 5592 3 0 0 25 0 1 0 900449519 23527424 5228 1283457024 134512640 136223643 4289824016 18446744073709551615 134928897 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31407/statm: 5744 5228 225 418 0 5324 0
Current children cumulated CPU time (s) 57.5
Current children cumulated vsize (KiB) 25568

[startup+60.8089 s]
/proc/loadavg: 1.02 1.03 1.00 2/40 31409
/proc/meminfo: memFree=358604/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=1.55
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 17770 0 0 0 0 147 8 15 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
[pid=31407] ppid=31398 vsize=22976 CPUtime=59.15
/proc/31407/stat : 31407 (clasp) R 31398 31398 25521 34816 25544 4202496 6168 0 0 0 5912 3 0 0 25 0 1 0 900449519 23527424 5228 1283457024 134512640 136223643 4289824016 18446744073709551615 134931000 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31407/statm: 5744 5228 225 418 0 5324 0
Current children cumulated CPU time (s) 60.7
Current children cumulated vsize (KiB) 25568

[startup+62.4094 s]
/proc/loadavg: 1.02 1.03 1.00 2/40 31409
/proc/meminfo: memFree=358604/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=1.55
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 17770 0 0 0 0 147 8 15 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
[pid=31407] ppid=31398 vsize=22976 CPUtime=60.76
/proc/31407/stat : 31407 (clasp) R 31398 31398 25521 34816 25544 4202496 6168 0 0 0 6073 3 0 0 25 0 1 0 900449519 23527424 5228 1283457024 134512640 136223643 4289824016 18446744073709551615 134929484 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31407/statm: 5744 5228 225 418 0 5324 0
Current children cumulated CPU time (s) 62.31
Current children cumulated vsize (KiB) 25568

[startup+64.0098 s]
/proc/loadavg: 1.02 1.03 1.00 2/40 31409
/proc/meminfo: memFree=358604/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=1.55
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 17770 0 0 0 0 147 8 15 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
[pid=31407] ppid=31398 vsize=22976 CPUtime=62.35
/proc/31407/stat : 31407 (clasp) R 31398 31398 25521 34816 25544 4202496 6168 0 0 0 6232 3 0 0 25 0 1 0 900449519 23527424 5228 1283457024 134512640 136223643 4289824016 18446744073709551615 134929304 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31407/statm: 5744 5228 225 418 0 5324 0
Current children cumulated CPU time (s) 63.9
Current children cumulated vsize (KiB) 25568

[startup+64.81 s]
/proc/loadavg: 1.02 1.03 1.00 2/40 31409
/proc/meminfo: memFree=358604/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=1.55
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 17770 0 0 0 0 147 8 15 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
[pid=31407] ppid=31398 vsize=22976 CPUtime=63.15
/proc/31407/stat : 31407 (clasp) R 31398 31398 25521 34816 25544 4202496 6168 0 0 0 6312 3 0 0 25 0 1 0 900449519 23527424 5228 1283457024 134512640 136223643 4289824016 18446744073709551615 135602989 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31407/statm: 5744 5228 225 418 0 5324 0
Current children cumulated CPU time (s) 64.7
Current children cumulated vsize (KiB) 25568

[startup+65.0101 s]
/proc/loadavg: 1.02 1.03 1.00 2/40 31409
/proc/meminfo: memFree=358604/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=2592 CPUtime=1.55
/proc/31398/stat : 31398 (aspcud-1.3) S 31397 31398 25521 34816 25544 4202496 573 17770 0 0 0 0 147 8 15 0 1 0 900449518 2654208 299 1283457024 134512640 135304128 4294799840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31398/statm: 648 299 253 194 0 34 0
[pid=31407] ppid=31398 vsize=22976 CPUtime=63.35
/proc/31407/stat : 31407 (clasp) R 31398 31398 25521 34816 25544 4202496 6168 0 0 0 6332 3 0 0 25 0 1 0 900449519 23527424 5228 1283457024 134512640 136223643 4289824016 18446744073709551615 134630089 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/31407/statm: 5744 5228 225 418 0 5324 0
Current children cumulated CPU time (s) 64.9
Current children cumulated vsize (KiB) 25568

[startup+65.1172 s]
/proc/loadavg: 1.02 1.03 1.00 2/40 31409
/proc/meminfo: memFree=358604/1048576 swapFree=2095372/2097144
[pid=31398] ppid=31397 vsize=0 CPUtime=65.01
/proc/31398/stat : 31398 (aspcud-1.3) Z 31397 31398 25521 34816 25544 4202508 952 27145 0 0 0 0 6488 13 15 0 1 0 900449518 0 0 1283457024 0 0 0 0 0 0 0 16902 1132543225 18446744071564254338 0 0 17 0 0 0 0
/proc/31398/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 65.01
Current children cumulated vsize (KiB) 0

Child status: 0
Real time (s): 65.1173
CPU time (s): 65.0201
CPU user time (s): 64.8801
CPU system time (s): 0.140008
CPU usage (%): 99.8506
Max. virtual memory (cumulated for all children) (KiB): 48336

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 64.8801
system time used= 0.140008
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 28097
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 990
involuntary context switches= 1732

runsolver used 0 second user time and 0.012 second system time

The end