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/201108241238/aspcud-trendy-1.5/301cbe92-a79c-11e0-9181-00163e1e087d.cudf.dudf-real.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/dudf-real//301cbe92-a79c-11e0-9181-00163e1e087d.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/301cbe92-a79c-11e0-9181-00163e1e087d.cudf.dudf-real.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.28 1.09 1.02 5/35 16715
/proc/meminfo: memFree=466564/1048576 swapFree=0/0
[pid=16713] ppid=16712 vsize=2588 CPUtime=0
/proc/16713/stat : 16713 (aspcud-trendy-1) S 16712 16713 1511 34817 1511 4202496 375 0 0 0 0 0 0 0 18 0 1 0 3798186 2650112 280 1283457024 134512640 135304128 4292388736 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/16713/statm: 647 280 234 194 0 34 0
[pid=16714] ppid=16713 vsize=2588 CPUtime=0
/proc/16714/stat : 16714 (aspcud-trendy-1) R 16713 16713 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 3798187 2650112 133 1283457024 134512640 135304128 4292388736 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/16714/statm: 647 133 86 194 0 34 0
[pid=16715] ppid=16714 vsize=2588 CPUtime=0
/proc/16715/stat : 16715 (aspcud-trendy-1) R 16714 16713 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 3798187 2650112 47 1283457024 134512640 135304128 4292388736 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/16715/statm: 647 47 0 194 0 34 0

[startup+0.205119 s]
/proc/loadavg: 1.28 1.09 1.02 5/35 16715
/proc/meminfo: memFree=466564/1048576 swapFree=0/0
[pid=16713] ppid=16712 vsize=2596 CPUtime=0.01
/proc/16713/stat : 16713 (aspcud-trendy-1) S 16712 16713 1511 34817 1511 4202496 625 2230 0 0 0 0 0 1 25 0 1 0 3798186 2658304 299 1283457024 134512640 135304128 4292388736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16713/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.305133 s]
/proc/loadavg: 1.28 1.09 1.02 5/35 16715
/proc/meminfo: memFree=466564/1048576 swapFree=0/0
[pid=16713] ppid=16712 vsize=2596 CPUtime=0.01
/proc/16713/stat : 16713 (aspcud-trendy-1) S 16712 16713 1511 34817 1511 4202496 625 2230 0 0 0 0 0 1 25 0 1 0 3798186 2658304 299 1283457024 134512640 135304128 4292388736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16713/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.405143 s]
/proc/loadavg: 1.28 1.09 1.02 5/35 16715
/proc/meminfo: memFree=466564/1048576 swapFree=0/0
[pid=16713] ppid=16712 vsize=2596 CPUtime=0.01
/proc/16713/stat : 16713 (aspcud-trendy-1) S 16712 16713 1511 34817 1511 4202496 625 2230 0 0 0 0 0 1 25 0 1 0 3798186 2658304 299 1283457024 134512640 135304128 4292388736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16713/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.705208 s]
/proc/loadavg: 1.28 1.09 1.02 5/35 16715
/proc/meminfo: memFree=466564/1048576 swapFree=0/0
[pid=16713] ppid=16712 vsize=2596 CPUtime=0.01
/proc/16713/stat : 16713 (aspcud-trendy-1) S 16712 16713 1511 34817 1511 4202496 625 2230 0 0 0 0 0 1 25 0 1 0 3798186 2658304 299 1283457024 134512640 135304128 4292388736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16713/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+1.50542 s]
/proc/loadavg: 1.26 1.08 1.02 2/37 16727
/proc/meminfo: memFree=444828/1048576 swapFree=0/0
[pid=16713] ppid=16712 vsize=2596 CPUtime=0.01
/proc/16713/stat : 16713 (aspcud-trendy-1) S 16712 16713 1511 34817 1511 4202496 625 2230 0 0 0 0 0 1 25 0 1 0 3798186 2658304 299 1283457024 134512640 135304128 4292388736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16713/statm: 649 299 251 194 0 36 0
[pid=16725] ppid=16713 vsize=1924 CPUtime=0
/proc/16725/stat : 16725 (clasp) S 16713 16713 1511 34817 1511 4202496 292 0 0 0 0 0 0 0 25 0 1 0 3798188 1970176 159 1283457024 134512640 136285277 4287785744 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/16725/statm: 481 159 144 433 0 46 0
[pid=16726] ppid=16713 vsize=2584 CPUtime=0
/proc/16726/stat : 16726 (gringo) S 16713 16713 1511 34817 1511 4202496 404 0 0 0 0 0 0 0 25 0 1 0 3798188 2646016 271 1283457024 134512640 136933539 4290932368 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/16726/statm: 646 271 242 592 0 51 0
[pid=16727] ppid=16713 vsize=36496 CPUtime=1.49
/proc/16727/stat : 16727 (cudf2lp) R 16713 16713 1511 34817 1511 4202496 10431 0 0 0 147 2 0 0 25 0 1 0 3798188 37371904 8727 1283457024 134512640 135786343 4293224656 18446744073709551615 134582300 0 0 6 0 0 0 0 17 0 0 0 0
/proc/16727/statm: 9124 8727 133 311 0 8811 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 43600

[startup+3.10587 s]
/proc/loadavg: 1.26 1.08 1.02 3/37 16727
/proc/meminfo: memFree=409116/1048576 swapFree=0/0
[pid=16713] ppid=16712 vsize=2596 CPUtime=1.88
/proc/16713/stat : 16713 (aspcud-trendy-1) S 16712 16713 1511 34817 1511 4202496 626 14735 0 0 0 0 180 8 18 0 1 0 3798186 2658304 299 1283457024 134512640 135304128 4292388736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16713/statm: 649 299 251 194 0 36 0
[pid=16725] ppid=16713 vsize=24212 CPUtime=0.14
/proc/16725/stat : 16725 (clasp) R 16713 16713 1511 34817 1511 4202496 6673 0 0 0 11 3 0 0 18 0 1 0 3798188 24793088 5679 1283457024 134512640 136285277 4287785744 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/16725/statm: 6053 5679 177 433 0 5618 0
[pid=16726] ppid=16713 vsize=45712 CPUtime=1.07
/proc/16726/stat : 16726 (gringo) R 16713 16713 1511 34817 1511 4202496 12049 0 0 0 101 6 0 0 18 0 1 0 3798188 46809088 8203 1283457024 134512640 136933539 4290932368 18446744073709551615 134685860 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16726/statm: 11428 8203 253 592 0 10833 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 72520

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

[startup+3.30594 s]
/proc/loadavg: 1.26 1.08 1.02 3/37 16727
/proc/meminfo: memFree=409116/1048576 swapFree=0/0
[pid=16713] ppid=16712 vsize=2596 CPUtime=1.88
/proc/16713/stat : 16713 (aspcud-trendy-1) S 16712 16713 1511 34817 1511 4202496 626 14735 0 0 0 0 180 8 18 0 1 0 3798186 2658304 299 1283457024 134512640 135304128 4292388736 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16713/statm: 649 299 251 194 0 36 0
[pid=16725] ppid=16713 vsize=29700 CPUtime=0.22
/proc/16725/stat : 16725 (clasp) S 16713 16713 1511 34817 1511 4202496 8041 0 0 0 19 3 0 0 18 0 1 0 3798188 30412800 7047 1283457024 134512640 136285277 4287785744 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/16725/statm: 7425 7047 177 433 0 6990 0
[pid=16726] ppid=16713 vsize=40628 CPUtime=1.19
/proc/16726/stat : 16726 (gringo) R 16713 16713 1511 34817 1511 4202496 13715 0 0 0 112 7 0 0 19 0 1 0 3798188 41603072 7873 1283457024 134512640 136933539 4290932368 18446744073709551615 135997923 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16726/statm: 10157 7873 254 592 0 9562 0
Current children cumulated CPU time (s) 3.29
Current children cumulated vsize (KiB) 72924

[startup+3.70604 s]
/proc/loadavg: 1.26 1.08 1.02 3/36 16727
/proc/meminfo: memFree=436916/1048576 swapFree=0/0
[pid=16713] ppid=16712 vsize=2600 CPUtime=3.7
/proc/16713/stat : 16713 (aspcud-trendy-1) R 16712 16713 1511 34817 1511 4202496 2181 53243 0 0 1 0 341 28 18 0 1 0 3798186 2662400 305 1283457024 134512640 135304128 4292388736 18446744073709551615 134616764 0 0 16902 1132543225 0 0 0 17 0 0 0 0
/proc/16713/statm: 650 305 256 194 0 37 0
Current children cumulated CPU time (s) 3.7
Current children cumulated vsize (KiB) 2600

Child status: 0
Real time (s): 3.70838
CPU time (s): 3.71223
CPU user time (s): 3.42421
CPU system time (s): 0.288018
CPU usage (%): 100.104
Max. virtual memory (cumulated for all children) (KiB): 78888

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.42421
system time used= 0.288018
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 55858
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= 1537
involuntary context switches= 1141

runsolver used 0 second user time and 0 second system time

The end