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/201108291842/aspcud-1.5/rand83.cudf.dudf-random.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-random//rand83.cudf /home/misc2010/tmp/201108291842/aspcud-1.5/rand83.cudf.dudf-random.result -notuptodate,-removed,-changed 

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.63 1.33 1.22 5/35 24783
/proc/meminfo: memFree=305540/1048576 swapFree=0/0
[pid=24782] ppid=24781 vsize=2584 CPUtime=0.01
/proc/24782/stat : 24782 (aspcud-1.5) R 24781 24782 17511 34816 17511 4202496 365 0 0 0 0 1 0 0 25 0 1 0 46317012 2646016 279 1283457024 134512640 135304128 4291534544 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/24782/statm: 646 279 234 194 0 33 0
[pid=24783] ppid=24782 vsize=2584 CPUtime=0
/proc/24783/stat : 24783 (aspcud-1.5) R 24782 24782 17511 34816 17511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 46317012 2646016 45 1283457024 134512640 135304128 4291534544 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/24783/statm: 646 45 0 194 0 33 0

[startup+0.191659 s]
/proc/loadavg: 1.63 1.33 1.22 5/35 24783
/proc/meminfo: memFree=305540/1048576 swapFree=0/0
[pid=24782] ppid=24781 vsize=2592 CPUtime=0.01
/proc/24782/stat : 24782 (aspcud-1.5) S 24781 24782 17511 34816 17511 4202496 578 1522 0 0 0 1 0 0 25 0 1 0 46317012 2654208 298 1283457024 134512640 135304128 4291534544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24782/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.210715 s]
/proc/loadavg: 1.63 1.33 1.22 5/35 24783
/proc/meminfo: memFree=305540/1048576 swapFree=0/0
[pid=24782] ppid=24781 vsize=2592 CPUtime=0.01
/proc/24782/stat : 24782 (aspcud-1.5) S 24781 24782 17511 34816 17511 4202496 578 1522 0 0 0 1 0 0 25 0 1 0 46317012 2654208 298 1283457024 134512640 135304128 4291534544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24782/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.305397 s]
/proc/loadavg: 1.63 1.33 1.22 5/35 24783
/proc/meminfo: memFree=305540/1048576 swapFree=0/0
[pid=24782] ppid=24781 vsize=2592 CPUtime=0.01
/proc/24782/stat : 24782 (aspcud-1.5) S 24781 24782 17511 34816 17511 4202496 578 1522 0 0 0 1 0 0 25 0 1 0 46317012 2654208 298 1283457024 134512640 135304128 4291534544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24782/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.705412 s]
/proc/loadavg: 1.63 1.33 1.22 5/35 24783
/proc/meminfo: memFree=305540/1048576 swapFree=0/0
[pid=24782] ppid=24781 vsize=2592 CPUtime=0.01
/proc/24782/stat : 24782 (aspcud-1.5) S 24781 24782 17511 34816 17511 4202496 578 1522 0 0 0 1 0 0 25 0 1 0 46317012 2654208 298 1283457024 134512640 135304128 4291534544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24782/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.50549 s]
/proc/loadavg: 1.63 1.33 1.22 1/38 24793
/proc/meminfo: memFree=275552/1048576 swapFree=0/0
[pid=24782] ppid=24781 vsize=2592 CPUtime=0.01
/proc/24782/stat : 24782 (aspcud-1.5) S 24781 24782 17511 34816 17511 4202496 578 1522 0 0 0 1 0 0 25 0 1 0 46317012 2654208 298 1283457024 134512640 135304128 4291534544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24782/statm: 648 298 251 194 0 35 0
[pid=24791] ppid=24782 vsize=1928 CPUtime=0
/proc/24791/stat : 24791 (clasp) S 24782 24782 17511 34816 17511 4202496 291 0 0 0 0 0 0 0 25 0 1 0 46317013 1974272 159 1283457024 134512640 136285277 4289748224 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/24791/statm: 482 159 144 433 0 47 0
[pid=24792] ppid=24782 vsize=2588 CPUtime=0
/proc/24792/stat : 24792 (gringo) S 24782 24782 17511 34816 17511 4202496 404 0 0 0 0 0 0 0 25 0 1 0 46317013 2650112 272 1283457024 134512640 136933539 4288570464 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/24792/statm: 647 272 242 592 0 52 0
[pid=24793] ppid=24782 vsize=25008 CPUtime=1.14
/proc/24793/stat : 24793 (cudf2lp) D 24782 24782 17511 34816 17511 4202496 7047 0 0 0 111 3 0 0 25 0 1 0 46317013 25608192 5449 1283457024 134512640 135786343 4288791696 18446744073709551615 135258478 0 0 6 0 18446744071564332000 0 0 17 0 0 0 0
/proc/24793/statm: 6252 5449 128 311 0 5939 0
Current children cumulated CPU time (s) 1.15
Current children cumulated vsize (KiB) 32116

[startup+3.10885 s]
/proc/loadavg: 1.63 1.33 1.22 2/38 24793
/proc/meminfo: memFree=258012/1048576 swapFree=0/0
[pid=24782] ppid=24781 vsize=2592 CPUtime=0.01
/proc/24782/stat : 24782 (aspcud-1.5) S 24781 24782 17511 34816 17511 4202496 578 1522 0 0 0 1 0 0 25 0 1 0 46317012 2654208 298 1283457024 134512640 135304128 4291534544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24782/statm: 648 298 251 194 0 35 0
[pid=24791] ppid=24782 vsize=6796 CPUtime=0.01
/proc/24791/stat : 24791 (clasp) S 24782 24782 17511 34816 17511 4202496 1626 0 0 0 1 0 0 0 18 0 1 0 46317013 6959104 1412 1283457024 134512640 136285277 4289748224 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/24791/statm: 1699 1412 177 433 0 1264 0
[pid=24792] ppid=24782 vsize=9304 CPUtime=0.26
/proc/24792/stat : 24792 (gringo) R 24782 24782 17511 34816 17511 4202496 2436 0 0 0 25 1 0 0 18 0 1 0 46317013 9527296 1707 1283457024 134512640 136933539 4288570464 18446744073709551615 136183465 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/24792/statm: 2326 1707 242 592 0 1731 0
[pid=24793] ppid=24782 vsize=40944 CPUtime=2
/proc/24793/stat : 24793 (cudf2lp) R 24782 24782 17511 34816 17511 4202496 12904 0 0 0 195 5 0 0 25 0 1 0 46317013 41926656 10036 1283457024 134512640 135786343 4288791696 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/24793/statm: 10236 10036 139 311 0 9923 0
Current children cumulated CPU time (s) 2.28
Current children cumulated vsize (KiB) 59636
heavy processes:

[startup+6.30967 s]
/proc/loadavg: 1.66 1.34 1.22 2/36 24793
/proc/meminfo: memFree=245936/1048576 swapFree=0/0
[pid=24782] ppid=24781 vsize=2592 CPUtime=3.29
/proc/24782/stat : 24782 (aspcud-1.5) S 24781 24782 17511 34816 17511 4202496 579 25526 0 0 0 1 318 10 15 0 1 0 46317012 2654208 298 1283457024 134512640 135304128 4291534544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24782/statm: 648 298 251 194 0 35 0
[pid=24791] ppid=24782 vsize=33444 CPUtime=2.19
/proc/24791/stat : 24791 (clasp) R 24782 24782 17511 34816 17511 4202496 9953 0 0 0 214 5 0 0 21 0 1 0 46317013 34246656 8102 1283457024 134512640 136285277 4289748224 18446744073709551615 134686782 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/24791/statm: 8361 8102 234 433 0 7926 0
Current children cumulated CPU time (s) 5.48
Current children cumulated vsize (KiB) 36036

[startup+12.7109 s]
/proc/loadavg: 1.68 1.35 1.22 2/36 24793
/proc/meminfo: memFree=148976/1048576 swapFree=0/0
[pid=24782] ppid=24781 vsize=2592 CPUtime=3.29
/proc/24782/stat : 24782 (aspcud-1.5) S 24781 24782 17511 34816 17511 4202496 579 25526 0 0 0 1 318 10 15 0 1 0 46317012 2654208 298 1283457024 134512640 135304128 4291534544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24782/statm: 648 298 251 194 0 35 0
[pid=24791] ppid=24782 vsize=144368 CPUtime=8.58
/proc/24791/stat : 24791 (clasp) R 24782 24782 17511 34816 17511 4202496 37701 0 0 0 844 14 0 0 25 0 1 0 46317013 147832832 35850 1283457024 134512640 136285277 4289748224 18446744073709551615 134945930 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/24791/statm: 36092 35850 234 433 0 35657 0
Current children cumulated CPU time (s) 11.87
Current children cumulated vsize (KiB) 146960

[startup+25.504 s]
/proc/loadavg: 1.53 1.33 1.22 2/36 24793
/proc/meminfo: memFree=5880/1048576 swapFree=0/0
[pid=24782] ppid=24781 vsize=2592 CPUtime=3.29
/proc/24782/stat : 24782 (aspcud-1.5) S 24781 24782 17511 34816 17511 4202496 579 25526 0 0 0 1 318 10 15 0 1 0 46317012 2654208 298 1283457024 134512640 135304128 4291534544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24782/statm: 648 298 251 194 0 35 0
[pid=24791] ppid=24782 vsize=290204 CPUtime=21.36
/proc/24791/stat : 24791 (clasp) R 24782 24782 17511 34816 17511 4202496 74149 0 0 0 2109 27 0 0 25 0 1 0 46317013 297168896 72298 1283457024 134512640 136285277 4289748224 18446744073709551615 134966680 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/24791/statm: 72551 72298 234 433 0 72116 0
Current children cumulated CPU time (s) 24.65
Current children cumulated vsize (KiB) 292796

[startup+51.1105 s]
/proc/loadavg: 1.35 1.31 1.21 2/35 24793
/proc/meminfo: memFree=7404/1048576 swapFree=0/0
[pid=24782] ppid=24781 vsize=2592 CPUtime=3.29
/proc/24782/stat : 24782 (aspcud-1.5) S 24781 24782 17511 34816 17511 4202496 579 25526 0 0 0 1 318 10 15 0 1 0 46317012 2654208 298 1283457024 134512640 135304128 4291534544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24782/statm: 648 298 251 194 0 35 0
[pid=24791] ppid=24782 vsize=415500 CPUtime=46.9
/proc/24791/stat : 24791 (clasp) R 24782 24782 17511 34816 17511 4202496 105909 0 0 0 4644 46 0 0 25 0 1 0 46317013 425472000 103649 1283457024 134512640 136285277 4289748224 18446744073709551615 134955172 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/24791/statm: 103875 103649 234 433 0 103440 0
Current children cumulated CPU time (s) 50.19
Current children cumulated vsize (KiB) 418092

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

[startup+51.2106 s]
/proc/loadavg: 1.35 1.31 1.21 2/35 24793
/proc/meminfo: memFree=7404/1048576 swapFree=0/0
[pid=24782] ppid=24781 vsize=2592 CPUtime=3.29
/proc/24782/stat : 24782 (aspcud-1.5) S 24781 24782 17511 34816 17511 4202496 579 25526 0 0 0 1 318 10 15 0 1 0 46317012 2654208 298 1283457024 134512640 135304128 4291534544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24782/statm: 648 298 251 194 0 35 0
[pid=24791] ppid=24782 vsize=415500 CPUtime=47
/proc/24791/stat : 24791 (clasp) R 24782 24782 17511 34816 17511 4202496 105909 0 0 0 4654 46 0 0 25 0 1 0 46317013 425472000 103649 1283457024 134512640 136285277 4289748224 18446744073709551615 134965023 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/24791/statm: 103875 103649 234 433 0 103440 0
Current children cumulated CPU time (s) 50.29
Current children cumulated vsize (KiB) 418092

[startup+52.0108 s]
/proc/loadavg: 1.35 1.31 1.21 2/35 24793
/proc/meminfo: memFree=7404/1048576 swapFree=0/0
[pid=24782] ppid=24781 vsize=2592 CPUtime=3.29
/proc/24782/stat : 24782 (aspcud-1.5) S 24781 24782 17511 34816 17511 4202496 579 25526 0 0 0 1 318 10 15 0 1 0 46317012 2654208 298 1283457024 134512640 135304128 4291534544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24782/statm: 648 298 251 194 0 35 0
[pid=24791] ppid=24782 vsize=415500 CPUtime=47.8
/proc/24791/stat : 24791 (clasp) R 24782 24782 17511 34816 17511 4202496 105909 0 0 0 4734 46 0 0 25 0 1 0 46317013 425472000 103649 1283457024 134512640 136285277 4289748224 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/24791/statm: 103875 103649 234 433 0 103440 0
Current children cumulated CPU time (s) 51.09
Current children cumulated vsize (KiB) 418092

[startup+52.4108 s]
/proc/loadavg: 1.35 1.31 1.21 2/35 24793
/proc/meminfo: memFree=7404/1048576 swapFree=0/0
[pid=24782] ppid=24781 vsize=2592 CPUtime=3.29
/proc/24782/stat : 24782 (aspcud-1.5) S 24781 24782 17511 34816 17511 4202496 579 25526 0 0 0 1 318 10 15 0 1 0 46317012 2654208 298 1283457024 134512640 135304128 4291534544 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/24782/statm: 648 298 251 194 0 35 0
[pid=24791] ppid=24782 vsize=415500 CPUtime=48.2
/proc/24791/stat : 24791 (clasp) R 24782 24782 17511 34816 17511 4202496 105909 0 0 0 4774 46 0 0 25 0 1 0 46317013 425472000 103649 1283457024 134512640 136285277 4289748224 18446744073709551615 134955235 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/24791/statm: 103875 103649 234 433 0 103440 0
Current children cumulated CPU time (s) 51.49
Current children cumulated vsize (KiB) 418092

[startup+52.6109 s]
/proc/loadavg: 1.35 1.31 1.21 2/35 24793
/proc/meminfo: memFree=7404/1048576 swapFree=0/0
[pid=24782] ppid=24781 vsize=2788 CPUtime=51.7
/proc/24782/stat : 24782 (aspcud-1.5) R 24781 24782 17511 34816 17511 4202496 843 133259 0 0 0 1 5101 68 20 0 1 0 46317012 2854912 352 1283457024 134512640 135304128 4291534544 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/24782/statm: 697 352 256 194 0 84 0
Current children cumulated CPU time (s) 51.7
Current children cumulated vsize (KiB) 2788

Child status: 0
Real time (s): 52.622
CPU time (s): 51.7312
CPU user time (s): 51.0192
CPU system time (s): 0.712044
CPU usage (%): 98.3072
Max. virtual memory (cumulated for all children) (KiB): 419856

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 51.0192
system time used= 0.712044
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 135874
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= 1335
involuntary context switches= 1758

runsolver used 0 second user time and 0 second system time

The end