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/201012061533/aspcud-paranoid-1.3/randfa4522.cudf.impossible.log.runsolver ./aspcud-paranoid-1.3 /home/misc2010/data/2010/impossible//randfa4522.cudf /home/misc2010/tmp/201012061533/aspcud-paranoid-1.3/randfa4522.cudf.impossible.result 

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.11 1.20 1.22 2/46 32431
/proc/meminfo: memFree=903832/1048576 swapFree=2078680/2097144
[pid=32431] ppid=32430 vsize=3028 CPUtime=0
/proc/32431/stat : 32431 (runsolver) D 32430 32431 2059 34821 2220 4202560 72 0 0 0 0 0 0 0 25 0 1 0 876678670 3100672 94 1283457024 134512640 134586868 4287222256 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/32431/statm: 757 94 62 19 0 55 0

[startup+0.181719 s]
/proc/loadavg: 1.11 1.20 1.22 2/46 32431
/proc/meminfo: memFree=903832/1048576 swapFree=2078680/2097144
[pid=32431] ppid=32430 vsize=2596 CPUtime=0
/proc/32431/stat : 32431 (aspcud-paranoid) S 32430 32431 2059 34821 2220 4202496 662 2929 0 3 0 0 0 0 25 0 1 0 876678670 2658304 300 1283457024 134512640 135304128 4286929520 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32431/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.205716 s]
/proc/loadavg: 1.11 1.20 1.22 2/46 32431
/proc/meminfo: memFree=903832/1048576 swapFree=2078680/2097144
[pid=32431] ppid=32430 vsize=2596 CPUtime=0
/proc/32431/stat : 32431 (aspcud-paranoid) S 32430 32431 2059 34821 2220 4202496 662 2929 0 3 0 0 0 0 25 0 1 0 876678670 2658304 300 1283457024 134512640 135304128 4286929520 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32431/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.311168 s]
/proc/loadavg: 1.11 1.20 1.22 2/46 32431
/proc/meminfo: memFree=903832/1048576 swapFree=2078680/2097144
[pid=32431] ppid=32430 vsize=2596 CPUtime=0
/proc/32431/stat : 32431 (aspcud-paranoid) S 32430 32431 2059 34821 2220 4202496 662 2929 0 3 0 0 0 0 25 0 1 0 876678670 2658304 300 1283457024 134512640 135304128 4286929520 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32431/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.711277 s]
/proc/loadavg: 1.11 1.20 1.22 2/46 32431
/proc/meminfo: memFree=903832/1048576 swapFree=2078680/2097144
[pid=32431] ppid=32430 vsize=2596 CPUtime=0
/proc/32431/stat : 32431 (aspcud-paranoid) S 32430 32431 2059 34821 2220 4202496 662 2929 0 3 0 0 0 0 25 0 1 0 876678670 2658304 300 1283457024 134512640 135304128 4286929520 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32431/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.51151 s]
/proc/loadavg: 1.11 1.20 1.22 2/50 32448
/proc/meminfo: memFree=865892/1048576 swapFree=2078680/2097144
[pid=32431] ppid=32430 vsize=2596 CPUtime=0
/proc/32431/stat : 32431 (aspcud-paranoid) S 32430 32431 2059 34821 2220 4202496 662 2929 0 3 0 0 0 0 25 0 1 0 876678670 2658304 300 1283457024 134512640 135304128 4286929520 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32431/statm: 649 300 253 194 0 35 0
[pid=32446] ppid=32431 vsize=1872 CPUtime=0
/proc/32446/stat : 32446 (clasp) S 32431 32431 2059 34821 2220 4202496 269 0 16 0 0 0 0 0 23 0 1 0 876678676 1916928 153 1283457024 134512640 136223643 4289508528 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/32446/statm: 468 153 138 418 0 48 0
[pid=32447] ppid=32431 vsize=2604 CPUtime=0
/proc/32447/stat : 32447 (gringo) S 32431 32431 2059 34821 2220 4202496 383 0 23 0 0 0 0 0 23 0 1 0 876678676 2666496 276 1283457024 134512640 136959103 4291735360 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/32447/statm: 651 276 247 598 0 50 0
[pid=32448] ppid=32431 vsize=47724 CPUtime=1.22
/proc/32448/stat : 32448 (cudf2lp) R 32431 32431 2059 34821 2220 4202496 13261 0 14 0 115 7 0 0 25 0 1 0 876678676 48869376 11121 1283457024 134512640 135749571 4286964432 18446744073709551615 134549717 0 0 6 0 0 0 0 17 0 0 0 0
/proc/32448/statm: 11931 11121 127 302 0 11627 0
Current children cumulated CPU time (s) 1.22
Current children cumulated vsize (KiB) 54796

[startup+3.11202 s]
/proc/loadavg: 1.10 1.20 1.22 3/50 32448
/proc/meminfo: memFree=831860/1048576 swapFree=2078680/2097144
[pid=32431] ppid=32430 vsize=2596 CPUtime=2.02
/proc/32431/stat : 32431 (aspcud-paranoid) S 32430 32431 2059 34821 2220 4202496 663 21935 0 18 0 0 192 10 18 0 1 0 876678670 2658304 300 1283457024 134512640 135304128 4286929520 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32431/statm: 649 300 253 194 0 35 0
[pid=32446] ppid=32431 vsize=16204 CPUtime=0.1
/proc/32446/stat : 32446 (clasp) R 32431 32431 2059 34821 2220 4202496 4471 0 19 0 8 2 0 0 18 0 1 0 876678676 16592896 3700 1283457024 134512640 136223643 4289508528 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/32446/statm: 4051 3700 174 418 0 3631 0
[pid=32447] ppid=32431 vsize=25356 CPUtime=0.68
/proc/32447/stat : 32447 (gringo) R 32431 32431 2059 34821 2220 4202496 7140 0 23 0 68 0 0 0 18 0 1 0 876678676 25964544 4861 1283457024 134512640 136959103 4291735360 18446744073709551615 136227623 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/32447/statm: 6339 4861 256 598 0 5738 0
Current children cumulated CPU time (s) 2.8
Current children cumulated vsize (KiB) 44156

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

[startup+3.20204 s]
/proc/loadavg: 1.10 1.20 1.22 3/50 32448
/proc/meminfo: memFree=831860/1048576 swapFree=2078680/2097144
[pid=32431] ppid=32430 vsize=2596 CPUtime=2.02
/proc/32431/stat : 32431 (aspcud-paranoid) S 32430 32431 2059 34821 2220 4202496 663 21935 0 18 0 0 192 10 18 0 1 0 876678670 2658304 300 1283457024 134512640 135304128 4286929520 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32431/statm: 649 300 253 194 0 35 0
[pid=32446] ppid=32431 vsize=17804 CPUtime=0.12
/proc/32446/stat : 32446 (clasp) R 32431 32431 2059 34821 2220 4202496 4866 0 19 0 10 2 0 0 18 0 1 0 876678676 18231296 4095 1283457024 134512640 136223643 4289508528 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/32446/statm: 4451 4095 174 418 0 4031 0
[pid=32447] ppid=32431 vsize=29152 CPUtime=0.76
/proc/32447/stat : 32447 (gringo) R 32431 32431 2059 34821 2220 4202496 8393 0 23 0 76 0 0 0 18 0 1 0 876678676 29851648 5728 1283457024 134512640 136959103 4291735360 18446744073709551615 134694923 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/32447/statm: 7288 5728 256 598 0 6687 0
Current children cumulated CPU time (s) 2.9
Current children cumulated vsize (KiB) 49552

[startup+4.01465 s]
/proc/loadavg: 1.10 1.20 1.22 3/49 32448
/proc/meminfo: memFree=855872/1048576 swapFree=2078680/2097144
[pid=32431] ppid=32430 vsize=2596 CPUtime=3.29
/proc/32431/stat : 32431 (aspcud-paranoid) S 32430 32431 2059 34821 2220 4202496 663 34965 0 41 0 0 316 13 18 0 1 0 876678670 2658304 300 1283457024 134512640 135304128 4286929520 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32431/statm: 649 300 253 194 0 35 0
[pid=32446] ppid=32431 vsize=36284 CPUtime=0.41
/proc/32446/stat : 32446 (clasp) R 32431 32431 2059 34821 2220 4202496 9601 0 20 0 38 3 0 0 18 0 1 0 876678676 37154816 8176 1283457024 134512640 136223643 4289508528 18446744073709551615 134772201 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/32446/statm: 9071 8176 197 418 0 8651 0
Current children cumulated CPU time (s) 3.7
Current children cumulated vsize (KiB) 38880

[startup+4.21473 s]
/proc/loadavg: 1.10 1.20 1.22 3/49 32448
/proc/meminfo: memFree=855872/1048576 swapFree=2078680/2097144
[pid=32431] ppid=32430 vsize=2596 CPUtime=3.29
/proc/32431/stat : 32431 (aspcud-paranoid) S 32430 32431 2059 34821 2220 4202496 663 34965 0 41 0 0 316 13 18 0 1 0 876678670 2658304 300 1283457024 134512640 135304128 4286929520 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/32431/statm: 649 300 253 194 0 35 0
[pid=32446] ppid=32431 vsize=37528 CPUtime=0.61
/proc/32446/stat : 32446 (clasp) R 32431 32431 2059 34821 2220 4202496 10458 0 20 0 57 4 0 0 18 0 1 0 876678676 38428672 8598 1283457024 134512640 136223643 4289508528 18446744073709551615 134891364 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/32446/statm: 9382 8598 217 418 0 8962 0
Current children cumulated CPU time (s) 3.9
Current children cumulated vsize (KiB) 40124

Child status: 0
Real time (s): 4.2906
CPU time (s): 3.95625
CPU user time (s): 3.77224
CPU system time (s): 0.184011
CPU usage (%): 92.2073
Max. virtual memory (cumulated for all children) (KiB): 97648

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.77223
system time used= 0.184011
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 49683
page faults= 63
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1690
involuntary context switches= 1168

runsolver used 0 second user time and 0.004 second system time

The end