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/201103031013/uns-trendy-0.0004/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf.debian.log.runsolver ./uns-trendy-0.0004 /home/misc2010/data/misc4/debian//6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf /home/misc2010/tmp/201103031013/uns-trendy-0.0004/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf.debian.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.13 1.08 1.06 4/36 9536
/proc/meminfo: memFree=567108/1048576 swapFree=0/0
[pid=9535] ppid=9534 vsize=1668 CPUtime=0
/proc/9535/stat : 9535 (uns-trendy-0.00) S 9534 9535 29493 34817 29493 4202496 214 0 0 0 0 0 0 0 18 0 1 0 75287265 1708032 129 1283457024 134512640 134593992 4292362112 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9535/statm: 417 129 113 20 0 44 0
[pid=9536] ppid=9535 vsize=7700 CPUtime=0.01
/proc/9536/stat : 9536 (cudfsolver-stat) R 9535 9535 29493 34817 29493 4202496 285 0 0 0 1 0 0 0 25 0 1 0 75287266 7884800 242 1283457024 134512640 141746657 4289782960 18446744073709551615 134597531 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9536/statm: 1925 242 149 1767 0 135 0

[startup+0.156222 s]
/proc/loadavg: 1.13 1.08 1.06 4/36 9536
/proc/meminfo: memFree=567108/1048576 swapFree=0/0
[pid=9535] ppid=9534 vsize=1668 CPUtime=0
/proc/9535/stat : 9535 (uns-trendy-0.00) S 9534 9535 29493 34817 29493 4202496 214 0 0 0 0 0 0 0 18 0 1 0 75287265 1708032 129 1283457024 134512640 134593992 4292362112 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9535/statm: 417 129 113 20 0 44 0
[pid=9536] ppid=9535 vsize=14984 CPUtime=0.16
/proc/9536/stat : 9536 (cudfsolver-stat) R 9535 9535 29493 34817 29493 4202496 2135 0 0 0 16 0 0 0 25 0 1 0 75287266 15343616 2063 1283457024 134512640 141746657 4289782960 18446744073709551615 140906976 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9536/statm: 3746 2063 149 1767 0 1956 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 16652

[startup+0.206237 s]
/proc/loadavg: 1.13 1.08 1.06 4/36 9536
/proc/meminfo: memFree=567108/1048576 swapFree=0/0
[pid=9535] ppid=9534 vsize=1668 CPUtime=0
/proc/9535/stat : 9535 (uns-trendy-0.00) S 9534 9535 29493 34817 29493 4202496 214 0 0 0 0 0 0 0 18 0 1 0 75287265 1708032 129 1283457024 134512640 134593992 4292362112 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9535/statm: 417 129 113 20 0 44 0
[pid=9536] ppid=9535 vsize=17104 CPUtime=0.21
/proc/9536/stat : 9536 (cudfsolver-stat) R 9535 9535 29493 34817 29493 4202496 2675 0 0 0 20 1 0 0 25 0 1 0 75287266 17514496 2603 1283457024 134512640 141746657 4289782960 18446744073709551615 134598198 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9536/statm: 4276 2603 149 1767 0 2486 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 18772

[startup+0.306243 s]
/proc/loadavg: 1.13 1.08 1.06 4/36 9536
/proc/meminfo: memFree=567108/1048576 swapFree=0/0
[pid=9535] ppid=9534 vsize=1668 CPUtime=0
/proc/9535/stat : 9535 (uns-trendy-0.00) S 9534 9535 29493 34817 29493 4202496 214 0 0 0 0 0 0 0 18 0 1 0 75287265 1708032 129 1283457024 134512640 134593992 4292362112 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9535/statm: 417 129 113 20 0 44 0
[pid=9536] ppid=9535 vsize=21520 CPUtime=0.3
/proc/9536/stat : 9536 (cudfsolver-stat) R 9535 9535 29493 34817 29493 4202496 3798 0 0 0 28 2 0 0 25 0 1 0 75287266 22036480 3694 1283457024 134512640 141746657 4289782960 18446744073709551615 134636103 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9536/statm: 5380 3694 150 1767 0 3590 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 23188

[startup+0.706321 s]
/proc/loadavg: 1.13 1.08 1.06 4/36 9536
/proc/meminfo: memFree=567108/1048576 swapFree=0/0
[pid=9535] ppid=9534 vsize=1668 CPUtime=0
/proc/9535/stat : 9535 (uns-trendy-0.00) S 9534 9535 29493 34817 29493 4202496 214 0 0 0 0 0 0 0 18 0 1 0 75287265 1708032 129 1283457024 134512640 134593992 4292362112 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9535/statm: 417 129 113 20 0 44 0
[pid=9536] ppid=9535 vsize=37736 CPUtime=0.71
/proc/9536/stat : 9536 (cudfsolver-stat) R 9535 9535 29493 34817 29493 4202496 7866 0 0 0 65 6 0 0 25 0 1 0 75287266 38641664 7729 1283457024 134512640 141746657 4289782960 18446744073709551615 134636114 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9536/statm: 9434 7729 150 1767 0 7644 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 39404

[startup+1.50646 s]
/proc/loadavg: 1.13 1.08 1.06 2/37 9537
/proc/meminfo: memFree=521688/1048576 swapFree=0/0
[pid=9535] ppid=9534 vsize=1668 CPUtime=0
/proc/9535/stat : 9535 (uns-trendy-0.00) S 9534 9535 29493 34817 29493 4202496 214 0 0 0 0 0 0 0 18 0 1 0 75287265 1708032 129 1283457024 134512640 134593992 4292362112 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9535/statm: 417 129 113 20 0 44 0
[pid=9536] ppid=9535 vsize=68088 CPUtime=1.51
/proc/9536/stat : 9536 (cudfsolver-stat) R 9535 9535 29493 34817 29493 4202496 15616 0 0 0 140 11 0 0 25 0 1 0 75287266 69722112 15282 1283457024 134512640 141746657 4289782960 18446744073709551615 134632245 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9536/statm: 17022 15282 150 1767 0 15232 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 69756

[startup+3.10689 s]
/proc/loadavg: 1.13 1.08 1.06 2/37 9537
/proc/meminfo: memFree=470848/1048576 swapFree=0/0
[pid=9535] ppid=9534 vsize=1668 CPUtime=0
/proc/9535/stat : 9535 (uns-trendy-0.00) S 9534 9535 29493 34817 29493 4202496 214 0 0 0 0 0 0 0 18 0 1 0 75287265 1708032 129 1283457024 134512640 134593992 4292362112 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9535/statm: 417 129 113 20 0 44 0
[pid=9536] ppid=9535 vsize=120920 CPUtime=3.1
/proc/9536/stat : 9536 (cudfsolver-stat) R 9535 9535 29493 34817 29493 4202496 25544 0 0 0 298 12 0 0 25 0 1 0 75287266 123822080 24959 1283457024 134512640 141746657 4289782960 18446744073709551615 138846365 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9536/statm: 30230 24959 452 1767 0 28077 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 122588

[startup+6.30779 s]
/proc/loadavg: 1.12 1.08 1.06 2/37 9538
/proc/meminfo: memFree=468368/1048576 swapFree=0/0
[pid=9535] ppid=9534 vsize=1668 CPUtime=0
/proc/9535/stat : 9535 (uns-trendy-0.00) S 9534 9535 29493 34817 29493 4202496 214 0 0 0 0 0 0 0 18 0 1 0 75287265 1708032 129 1283457024 134512640 134593992 4292362112 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9535/statm: 417 129 113 20 0 44 0
[pid=9536] ppid=9535 vsize=120920 CPUtime=6.3
/proc/9536/stat : 9536 (cudfsolver-stat) R 9535 9535 29493 34817 29493 4202496 25771 0 0 0 618 12 0 0 25 0 1 0 75287266 123822080 25186 1283457024 134512640 141746657 4289782960 18446744073709551615 135510357 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9536/statm: 30230 25186 470 1767 0 28077 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 122588

[startup+12.7095 s]
/proc/loadavg: 1.11 1.08 1.06 2/37 9538
/proc/meminfo: memFree=435764/1048576 swapFree=0/0
[pid=9535] ppid=9534 vsize=1668 CPUtime=0
/proc/9535/stat : 9535 (uns-trendy-0.00) S 9534 9535 29493 34817 29493 4202496 214 0 0 0 0 0 0 0 18 0 1 0 75287265 1708032 129 1283457024 134512640 134593992 4292362112 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9535/statm: 417 129 113 20 0 44 0
[pid=9536] ppid=9535 vsize=149396 CPUtime=12.69
/proc/9536/stat : 9536 (cudfsolver-stat) R 9535 9535 29493 34817 29493 4202496 34882 0 0 0 1253 16 0 0 25 0 1 0 75287266 152981504 32116 1283457024 134512640 141746657 4289782960 18446744073709551615 138071876 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9536/statm: 37349 32116 690 1767 0 35196 0
Current children cumulated CPU time (s) 12.69
Current children cumulated vsize (KiB) 151064

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

[startup+12.8095 s]
/proc/loadavg: 1.11 1.08 1.06 2/37 9538
/proc/meminfo: memFree=435764/1048576 swapFree=0/0
[pid=9535] ppid=9534 vsize=1668 CPUtime=0
/proc/9535/stat : 9535 (uns-trendy-0.00) S 9534 9535 29493 34817 29493 4202496 214 0 0 0 0 0 0 0 18 0 1 0 75287265 1708032 129 1283457024 134512640 134593992 4292362112 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9535/statm: 417 129 113 20 0 44 0
[pid=9536] ppid=9535 vsize=149396 CPUtime=12.79
/proc/9536/stat : 9536 (cudfsolver-stat) R 9535 9535 29493 34817 29493 4202496 35104 0 0 0 1263 16 0 0 25 0 1 0 75287266 152981504 32338 1283457024 134512640 141746657 4289782960 18446744073709551615 138891484 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9536/statm: 37349 32338 739 1767 0 35196 0
Current children cumulated CPU time (s) 12.79
Current children cumulated vsize (KiB) 151064

[startup+16.0103 s]
/proc/loadavg: 1.10 1.08 1.06 2/37 9539
/proc/meminfo: memFree=394596/1048576 swapFree=0/0
[pid=9535] ppid=9534 vsize=1668 CPUtime=0
/proc/9535/stat : 9535 (uns-trendy-0.00) S 9534 9535 29493 34817 29493 4202496 214 0 0 0 0 0 0 0 18 0 1 0 75287265 1708032 129 1283457024 134512640 134593992 4292362112 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9535/statm: 417 129 113 20 0 44 0
[pid=9536] ppid=9535 vsize=199220 CPUtime=15.98
/proc/9536/stat : 9536 (cudfsolver-stat) R 9535 9535 29493 34817 29493 4202496 58757 0 0 0 1572 26 0 0 25 0 1 0 75287266 204001280 46987 1283457024 134512640 141746657 4289782960 18446744073709551615 134739947 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9536/statm: 49805 46987 837 1767 0 47652 0
Current children cumulated CPU time (s) 15.98
Current children cumulated vsize (KiB) 200888

[startup+17.6106 s]
/proc/loadavg: 1.10 1.08 1.06 2/37 9539
/proc/meminfo: memFree=384056/1048576 swapFree=0/0
[pid=9535] ppid=9534 vsize=1668 CPUtime=0
/proc/9535/stat : 9535 (uns-trendy-0.00) S 9534 9535 29493 34817 29493 4202496 214 0 0 0 0 0 0 0 18 0 1 0 75287265 1708032 129 1283457024 134512640 134593992 4292362112 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9535/statm: 417 129 113 20 0 44 0
[pid=9536] ppid=9535 vsize=195320 CPUtime=17.58
/proc/9536/stat : 9536 (cudfsolver-stat) R 9535 9535 29493 34817 29493 4202496 59312 0 0 0 1732 26 0 0 25 0 1 0 75287266 200007680 46566 1283457024 134512640 141746657 4289782960 18446744073709551615 136223314 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9536/statm: 48830 46566 841 1767 0 46677 0
Current children cumulated CPU time (s) 17.58
Current children cumulated vsize (KiB) 196988

[startup+18.4108 s]
/proc/loadavg: 1.10 1.08 1.06 2/37 9539
/proc/meminfo: memFree=384056/1048576 swapFree=0/0
[pid=9535] ppid=9534 vsize=1668 CPUtime=0
/proc/9535/stat : 9535 (uns-trendy-0.00) S 9534 9535 29493 34817 29493 4202496 214 0 0 0 0 0 0 0 18 0 1 0 75287265 1708032 129 1283457024 134512640 134593992 4292362112 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9535/statm: 417 129 113 20 0 44 0
[pid=9536] ppid=9535 vsize=162552 CPUtime=18.38
/proc/9536/stat : 9536 (cudfsolver-stat) R 9535 9535 29493 34817 29493 4202496 59312 0 0 0 1812 26 0 0 25 0 1 0 75287266 166453248 38375 1283457024 134512640 141746657 4289782960 18446744073709551615 138911252 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9536/statm: 40638 38375 841 1767 0 38485 0
Current children cumulated CPU time (s) 18.38
Current children cumulated vsize (KiB) 164220

[startup+19.2109 s]
/proc/loadavg: 1.10 1.08 1.06 2/37 9539
/proc/meminfo: memFree=416296/1048576 swapFree=0/0
[pid=9535] ppid=9534 vsize=1668 CPUtime=0
/proc/9535/stat : 9535 (uns-trendy-0.00) S 9534 9535 29493 34817 29493 4202496 214 0 0 0 0 0 0 0 18 0 1 0 75287265 1708032 129 1283457024 134512640 134593992 4292362112 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9535/statm: 417 129 113 20 0 44 0
[pid=9536] ppid=9535 vsize=162552 CPUtime=19.18
/proc/9536/stat : 9536 (cudfsolver-stat) R 9535 9535 29493 34817 29493 4202496 59313 0 0 0 1889 29 0 0 25 0 1 0 75287266 166453248 38375 1283457024 134512640 141746657 4289782960 18446744073709551615 135511103 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9536/statm: 40638 38375 841 1767 0 38485 0
Current children cumulated CPU time (s) 19.18
Current children cumulated vsize (KiB) 164220

[startup+19.4109 s]
/proc/loadavg: 1.10 1.08 1.06 2/37 9539
/proc/meminfo: memFree=416296/1048576 swapFree=0/0
[pid=9535] ppid=9534 vsize=1668 CPUtime=0
/proc/9535/stat : 9535 (uns-trendy-0.00) S 9534 9535 29493 34817 29493 4202496 214 0 0 0 0 0 0 0 18 0 1 0 75287265 1708032 129 1283457024 134512640 134593992 4292362112 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9535/statm: 417 129 113 20 0 44 0
[pid=9536] ppid=9535 vsize=162552 CPUtime=19.38
/proc/9536/stat : 9536 (cudfsolver-stat) R 9535 9535 29493 34817 29493 4202496 59315 0 0 0 1908 30 0 0 25 0 1 0 75287266 166453248 38377 1283457024 134512640 141746657 4289782960 18446744073709551615 138101967 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9536/statm: 40638 38377 843 1767 0 38485 0
Current children cumulated CPU time (s) 19.38
Current children cumulated vsize (KiB) 164220

[startup+19.5116 s]
/proc/loadavg: 1.10 1.08 1.06 2/37 9539
/proc/meminfo: memFree=416296/1048576 swapFree=0/0
[pid=9535] ppid=9534 vsize=1668 CPUtime=0
/proc/9535/stat : 9535 (uns-trendy-0.00) S 9534 9535 29493 34817 29493 4202496 214 0 0 0 0 0 0 0 18 0 1 0 75287265 1708032 129 1283457024 134512640 134593992 4292362112 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/9535/statm: 417 129 113 20 0 44 0
[pid=9536] ppid=9535 vsize=0 CPUtime=19.48
/proc/9536/stat : 9536 (cudfsolver-stat) R 9535 9535 29493 34817 29493 4202500 59373 0 0 0 1918 30 0 0 25 0 1 0 75287266 0 0 1283457024 0 0 0 0 0 0 0 0 0 0 0 0 17 0 0 0 0
/proc/9536/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 19.48
Current children cumulated vsize (KiB) 1668

Child status: 0
Real time (s): 19.5239
CPU time (s): 19.5012
CPU user time (s): 19.1812
CPU system time (s): 0.32002
CPU usage (%): 99.8839
Max. virtual memory (cumulated for all children) (KiB): 208908

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 19.1812
system time used= 0.32002
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 59588
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= 3
involuntary context switches= 251

runsolver used 0 second user time and 0 second system time

The end