Script 'mail_helper' called by obssrc
Hello community,
here is the log from the commit of package fortio for openSUSE:Factory checked
in at 2022-04-26 20:16:00
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
Comparing /work/SRC/openSUSE:Factory/fortio (Old)
and /work/SRC/openSUSE:Factory/.fortio.new.1538 (New)
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
Package is "fortio"
Tue Apr 26 20:16:00 2022 rev:9 rq:972900 version:1.28.0
Changes:
--------
--- /work/SRC/openSUSE:Factory/fortio/fortio.changes 2022-04-21
15:48:39.412316120 +0200
+++ /work/SRC/openSUSE:Factory/.fortio.new.1538/fortio.changes 2022-04-26
20:17:52.564768491 +0200
@@ -1,0 +2,6 @@
+Tue Apr 26 06:15:12 UTC 2022 - ka...@b1-systems.de
+
+- Update to version 1.28.0:
+ * Track success vs failure, add that and details string for richer access
log, visualize new errors histogram (#552)
+
+-------------------------------------------------------------------
Old:
----
fortio-1.27.0.tar.gz
New:
----
fortio-1.28.0.tar.gz
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
Other differences:
------------------
++++++ fortio.spec ++++++
--- /var/tmp/diff_new_pack.pXjp0L/_old 2022-04-26 20:17:53.192769251 +0200
+++ /var/tmp/diff_new_pack.pXjp0L/_new 2022-04-26 20:17:53.200769261 +0200
@@ -19,7 +19,7 @@
%define __arch_install_post export NO_BRP_STRIP_DEBUG=true
Name: fortio
-Version: 1.27.0
+Version: 1.28.0
Release: 0
Summary: Load testing library, command line tool, advanced echo server
and web UI
License: Apache-2.0
++++++ _service ++++++
--- /var/tmp/diff_new_pack.pXjp0L/_old 2022-04-26 20:17:53.232769300 +0200
+++ /var/tmp/diff_new_pack.pXjp0L/_new 2022-04-26 20:17:53.232769300 +0200
@@ -3,7 +3,7 @@
<param name="url">https://github.com/fortio/fortio</param>
<param name="scm">git</param>
<param name="exclude">.git</param>
- <param name="revision">v1.27.0</param>
+ <param name="revision">v1.28.0</param>
<param name="versionformat">@PARENT_TAG@</param>
<param name="changesgenerate">enable</param>
<param name="versionrewrite-pattern">v(.*)</param>
@@ -16,7 +16,7 @@
<param name="compression">gz</param>
</service>
<service name="go_modules" mode="disabled">
- <param name="archive">fortio-1.27.0.tar.gz</param>
+ <param name="archive">fortio-1.28.0.tar.gz</param>
</service>
</services>
++++++ _servicedata ++++++
--- /var/tmp/diff_new_pack.pXjp0L/_old 2022-04-26 20:17:53.252769324 +0200
+++ /var/tmp/diff_new_pack.pXjp0L/_new 2022-04-26 20:17:53.256769329 +0200
@@ -1,6 +1,6 @@
<servicedata>
<service name="tar_scm">
<param name="url">https://github.com/fortio/fortio</param>
- <param
name="changesrevision">450fe3dfe6302e1430d8eb00d37b4386f83ffd6d</param></service></servicedata>
+ <param
name="changesrevision">57e9d8f01c342a4c1b5d96f883f81128b04d991a</param></service></servicedata>
(No newline at EOF)
++++++ fortio-1.27.0.tar.gz -> fortio-1.28.0.tar.gz ++++++
diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn'
'--exclude=.svnignore' old/fortio-1.27.0/.circleci/config.yml
new/fortio-1.28.0/.circleci/config.yml
--- old/fortio-1.27.0/.circleci/config.yml 2022-04-18 21:54:08.000000000
+0200
+++ new/fortio-1.28.0/.circleci/config.yml 2022-04-26 02:16:27.000000000
+0200
@@ -22,10 +22,7 @@
- setup_remote_docker:
version: 20.10.12
- checkout
- - run: |
- docker context create release-tests
- docker buildx create release-tests --use
- make release-test BUILDX_PLATFORMS=linux/amd64
+ - run: make release-test
linters:
<<: *defaultEnv
steps:
diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn'
'--exclude=.svnignore' old/fortio-1.27.0/Makefile new/fortio-1.28.0/Makefile
--- old/fortio-1.27.0/Makefile 2022-04-18 21:54:08.000000000 +0200
+++ new/fortio-1.28.0/Makefile 2022-04-26 02:16:27.000000000 +0200
@@ -109,6 +109,9 @@
@echo 'Need to use gnu sed (brew install gnu-sed; make
update-build-image-tag SED=gsed)'
$(SED) --in-place=.bak -e
's!$(DOCKER_PREFIX).build:v..!$(BUILD_IMAGE)!g' $(FILES_WITH_IMAGE)
+docker-default-platform:
+ @docker buildx --builder default inspect | tail -1 | sed -e
"s/Platforms: //" -e "s/,//g" | awk '{print $$1}'
+
docker-version:
@echo "### Docker is `which docker`"
@docker version
diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn'
'--exclude=.svnignore' old/fortio-1.27.0/README.md new/fortio-1.28.0/README.md
--- old/fortio-1.27.0/README.md 2022-04-18 21:54:08.000000000 +0200
+++ new/fortio-1.28.0/README.md 2022-04-26 02:16:27.000000000 +0200
@@ -50,13 +50,13 @@
```shell
-curl -L
https://github.com/fortio/fortio/releases/download/v1.27.0/fortio-linux_amd64-1.27.0.tgz
\
+curl -L
https://github.com/fortio/fortio/releases/download/v1.28.0/fortio-linux_amd64-1.28.0.tgz
\
| sudo tar -C / -xvzpf -
# or the debian package
-wget
https://github.com/fortio/fortio/releases/download/v1.27.0/fortio_1.27.0_amd64.deb
-dpkg -i fortio_1.27.0_amd64.deb
+wget
https://github.com/fortio/fortio/releases/download/v1.28.0/fortio_1.28.0_amd64.deb
+dpkg -i fortio_1.28.0_amd64.deb
# or the rpm
-rpm -i
https://github.com/fortio/fortio/releases/download/v1.27.0/fortio-1.27.0-1.x86_64.rpm
+rpm -i
https://github.com/fortio/fortio/releases/download/v1.28.0/fortio-1.28.0-1.x86_64.rpm
# and more, see assets in release page
```
@@ -66,7 +66,7 @@
brew install fortio
```
-On Windows, download
https://github.com/fortio/fortio/releases/download/v1.27.0/fortio_win_1.27.0.zip
and extract `fortio.exe` to any location, then using the Windows Command
Prompt:
+On Windows, download
https://github.com/fortio/fortio/releases/download/v1.28.0/fortio_win_1.28.0.zip
and extract `fortio.exe` to any location, then using the Windows Command
Prompt:
```
fortio.exe server
```
@@ -112,7 +112,7 @@
<details>
<!-- use release/updateFlags.sh to update this section -->
<pre>
-???????????? 1.27.0 usage:
+???????????? 1.28.0 usage:
where command is one of: load (load testing), server (starts ui, http-echo,
redirect, proxies, tcp-echo and grpc ping servers), tcp-echo (only the
tcp-echo
server), report (report only UI server), redirect (only the redirect server),
@@ -381,6 +381,13 @@
14:11:05 I fortio_main.go:293> All fortio X.Y.Z unknown goM.m.p servers
started!
```
+### Sample of the graphing UI
+
+With the 2 histograms - total and errors overlayed
+
+
+
+
### Change the port / binding address
By default, Fortio's web/echo servers listen on port 8080 on all interfaces.
diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn'
'--exclude=.svnignore' old/fortio-1.27.0/Webtest.sh new/fortio-1.28.0/Webtest.sh
--- old/fortio-1.27.0/Webtest.sh 2022-04-18 21:54:08.000000000 +0200
+++ new/fortio-1.28.0/Webtest.sh 2022-04-26 02:16:27.000000000 +0200
@@ -14,7 +14,9 @@
# limitations under the License.
set -x
# Check we can build the image
-make docker-internal TAG=webtest || exit 1
+NATIVE_PLATFORM=$(docker buildx --builder default inspect | tail -1 | sed -e
"s/Platforms: //" -e "s/,//g" | awk '{print $1}')
+echo "Building for $NATIVE_PLATFORM"
+make docker-internal TAG=webtest BUILDX_PLATFORMS="$NATIVE_PLATFORM" || exit 1
FORTIO_UI_PREFIX=/newprefix/ # test the non default prefix (not /fortio/)
FILE_LIMIT=25 # must be low to detect leaks, go 1.14 seems to need more than
go1.8 (!)
LOGLEVEL=info # change to debug to debug
diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn'
'--exclude=.svnignore' old/fortio-1.27.0/fgrpc/grpcrunner.go
new/fortio-1.28.0/fgrpc/grpcrunner.go
--- old/fortio-1.27.0/fgrpc/grpcrunner.go 2022-04-18 21:54:08.000000000
+0200
+++ new/fortio-1.28.0/fgrpc/grpcrunner.go 2022-04-26 02:16:27.000000000
+0200
@@ -80,7 +80,7 @@
// Run exercises GRPC health check or ping at the target QPS.
// To be set as the Function in RunnerOptions.
-func (grpcstate *GRPCRunnerResults) Run(t int) {
+func (grpcstate *GRPCRunnerResults) Run(t int) (bool, string) {
log.Debugf("Calling in %d", t)
var err error
var res interface{}
@@ -99,9 +99,13 @@
if err != nil {
log.Warnf("Error making grpc call: %v", err)
grpcstate.RetCodes[Error]++
- } else {
- grpcstate.RetCodes[status.String()]++
+ return false, err.Error()
+ }
+ grpcstate.RetCodes[status.String()]++
+ if status == grpc_health_v1.HealthCheckResponse_SERVING {
+ return true, "SERVING"
}
+ return false, status.String()
}
// GRPCRunnerOptions includes the base RunnerOptions plus grpc specific
diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn'
'--exclude=.svnignore' old/fortio-1.27.0/fhttp/http_forwarder_test.go
new/fortio-1.28.0/fhttp/http_forwarder_test.go
--- old/fortio-1.27.0/fhttp/http_forwarder_test.go 2022-04-18
21:54:08.000000000 +0200
+++ new/fortio-1.28.0/fhttp/http_forwarder_test.go 2022-04-26
02:16:27.000000000 +0200
@@ -19,14 +19,8 @@
"fmt"
"net/http"
"testing"
-
- "fortio.org/fortio/log"
)
-func init() {
- log.SetLogLevel(log.Debug)
-}
-
func TestMultiProxy(t *testing.T) {
_, debugAddr := ServeTCP("0", "/debug")
urlBase := fmt.Sprintf("localhost:%d/", debugAddr.Port)
diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn'
'--exclude=.svnignore' old/fortio-1.27.0/fhttp/http_test.go
new/fortio-1.28.0/fhttp/http_test.go
--- old/fortio-1.27.0/fhttp/http_test.go 2022-04-18 21:54:08.000000000
+0200
+++ new/fortio-1.28.0/fhttp/http_test.go 2022-04-26 02:16:27.000000000
+0200
@@ -36,7 +36,6 @@
var uuids map[string]bool
func init() {
- log.SetLogLevel(log.Debug)
uuids = map[string]bool{}
}
diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn'
'--exclude=.svnignore' old/fortio-1.27.0/fhttp/httprunner.go
new/fortio-1.28.0/fhttp/httprunner.go
--- old/fortio-1.27.0/fhttp/httprunner.go 2022-04-18 21:54:08.000000000
+0200
+++ new/fortio-1.28.0/fhttp/httprunner.go 2022-04-26 02:16:27.000000000
+0200
@@ -16,6 +16,7 @@
import (
"fmt"
+ "net/http"
"os"
"runtime"
"runtime/pprof"
@@ -51,7 +52,7 @@
// Run tests http request fetching. Main call being run at the target QPS.
// To be set as the Function in RunnerOptions.
-func (httpstate *HTTPRunnerResults) Run(t int) {
+func (httpstate *HTTPRunnerResults) Run(t int) (bool, string) {
log.Debugf("Calling in %d", t)
code, body, headerSize := httpstate.client.Fetch()
size := len(body)
@@ -63,6 +64,10 @@
httpstate.aborter.Abort()
log.Infof("Aborted run because of code %d - data %s", code,
DebugSummary(body, 1024))
}
+ if code == http.StatusOK {
+ return true, "200"
+ }
+ return false, fmt.Sprint(code)
}
// HTTPRunnerOptions includes the base RunnerOptions plus http specific
diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn'
'--exclude=.svnignore' old/fortio-1.27.0/fhttp/httprunner_test.go
new/fortio-1.28.0/fhttp/httprunner_test.go
--- old/fortio-1.27.0/fhttp/httprunner_test.go 2022-04-18 21:54:08.000000000
+0200
+++ new/fortio-1.28.0/fhttp/httprunner_test.go 2022-04-26 02:16:27.000000000
+0200
@@ -16,10 +16,13 @@
package fhttp
import (
+ "bufio"
"bytes"
"compress/gzip"
"fmt"
"net/http"
+ "os"
+ "path"
"runtime"
"strings"
"testing"
@@ -80,7 +83,8 @@
t.Logf("Number go routine before test %d", ngBefore1)
mux, addr := DynamicHTTPServer(false)
mux.HandleFunc("/echo100", EchoHandler)
- url := fmt.Sprintf("http://localhost:%d/echo100";, addr.Port)
+ // Avoid using localhost which can timeout with stdclient (thought this
might fail on ipv6 only machines?)
+ url := fmt.Sprintf("http://127.0.0.1:%d/echo100";, addr.Port)
numCalls := 100
opts.NumThreads = numCalls / 2 // make 2 calls per thread
opts.Exactly = int64(numCalls)
@@ -247,6 +251,84 @@
return
}
+// nolint: gocognit
+func TestAccessLog(t *testing.T) {
+ mux, addr := DynamicHTTPServer(false)
+ mux.HandleFunc("/echo-for-alog/", EchoHandler)
+ URL := fmt.Sprintf("http://localhost:%d/echo-for-alog/?status=555:50";,
addr.Port)
+ opts := HTTPRunnerOptions{}
+ opts.Init(URL)
+ opts.QPS = 10
+ numReq := int64(50) // can't do too many without running out of fds on
mac
+ opts.Exactly = numReq
+ opts.NumThreads = 5
+ for _, format := range []string{"json", "influx"} {
+ dir := t.TempDir()
+ fname := path.Join(dir, "access.log")
+ err := opts.AddAccessLogger(fname, format)
+ if err != nil {
+ t.Errorf("unexpected error for log file %q %s: %v",
fname, format, err)
+ }
+ res, err := RunHTTPTest(&opts)
+ if err != nil {
+ t.Fatal(err)
+ }
+ totalReq := res.DurationHistogram.Count
+ if totalReq != numReq {
+ t.Errorf("Mismatch between requests %d and expected
%d", totalReq, numReq)
+ }
+ httpOk := res.RetCodes[http.StatusOK]
+ http555 := res.RetCodes[555]
+ if httpOk <= 1 || httpOk >= numReq-1 {
+ t.Errorf("Unexpected ok count %d should be ~ 50%% of
%d", httpOk, numReq)
+ }
+ if http555 <= 1 || http555 >= numReq-1 {
+ t.Errorf("Unexpected 555 count %d should be ~ 50%% of
%d", http555, numReq)
+ }
+ if totalReq != httpOk+http555 {
+ t.Errorf("Mismatch between requests %d and ok+555 %v",
totalReq, res.RetCodes)
+ }
+ file, _ := os.Open(fname)
+ scanner := bufio.NewScanner(file)
+ lineCount := 0
+ linesOk := 0
+ linesNotOk := 0
+ lines200 := 0
+ lines555 := 0
+ for scanner.Scan() {
+ line := scanner.Text()
+ if strings.Contains(line, "true") {
+ linesOk++
+ }
+ if strings.Contains(line, "false") {
+ linesNotOk++
+ }
+ if strings.Contains(line, "\"200\"") {
+ lines200++
+ }
+ if strings.Contains(line, "\"555\"") {
+ lines555++
+ }
+ lineCount++
+ }
+ if lineCount != int(numReq) {
+ t.Errorf("unexpected number of lines in access log %s:
%d", format, lineCount)
+ }
+ if linesOk != int(httpOk) {
+ t.Errorf("unexpected number of lines in access log %s:
with ok: %d instead of %d", format, linesOk, httpOk)
+ }
+ if lines200 != int(httpOk) {
+ t.Errorf("unexpected number of lines in access log %s:
with 200: %d instead of %d", format, lines200, httpOk)
+ }
+ if linesNotOk != int(http555) {
+ t.Errorf("unexpected number of lines in access log %s:
with not ok: %d instead of %d", format, linesNotOk, http555)
+ }
+ if lines555 != int(http555) {
+ t.Errorf("unexpected number of lines in access log %s:
with 555: %d instead of %d", format, lines555, http555)
+ }
+ }
+}
+
// need to be the last test as it installs Serve() which would make
// the error test for / url above fail:
diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn'
'--exclude=.svnignore' old/fortio-1.27.0/periodic/periodic.go
new/fortio-1.28.0/periodic/periodic.go
--- old/fortio-1.27.0/periodic/periodic.go 2022-04-18 21:54:08.000000000
+0200
+++ new/fortio-1.28.0/periodic/periodic.go 2022-04-26 02:16:27.000000000
+0200
@@ -52,7 +52,10 @@
// Runnable are the function to run periodically.
type Runnable interface {
- Run(tid int)
+ // Run returns a boolean, true for normal/success, false otherwise.
+ // with details being an optional string that can be put in the access
logs.
+ // Statistics are split into two sets.
+ Run(tid int) (status bool, details string)
}
// MakeRunners creates an array of NumThreads identical Runnable instances
@@ -159,13 +162,16 @@
ActualDuration time.Duration
NumThreads int
Version string
+ // DurationHistogram all the Run. If you want to exclude the error
cases; subtract ErrorsDurationHistogram to each bucket.
DurationHistogram *stats.HistogramData
- Exactly int64 // Echo back the requested count
- Jitter bool
- Uniform bool
- NoCatchUp bool
- RunID int64 // Echo back the optional run id
- AccessLoggerInfo string
+ // ErrorsDurationHistogram is the durations of the error (Run returning
false) cases.
+ ErrorsDurationHistogram *stats.HistogramData
+ Exactly int64 // Echo back the requested count
+ Jitter bool
+ Uniform bool
+ NoCatchUp bool
+ RunID int64 // Echo back the optional run id
+ AccessLoggerInfo string
}
// HasRunnerResult is the interface implictly implemented by HTTPRunnerResults
@@ -397,7 +403,7 @@
// Run starts the runner.
func (r *periodicRunner) Run() RunnerResults {
r.Stop.Lock()
- runnerChan := r.Stop.StopChan // need a copy to not race with
assignement to nil
+ runnerChan := r.Stop.StopChan // need a copy to not race with
assignment to nil
r.Stop.Unlock()
useQPS := (r.QPS > 0)
// r.Exactly is > 0 if we use Exactly iterations instead of the
duration.
@@ -427,19 +433,21 @@
start := time.Now()
// Histogram and stats for Function duration - millisecond precision
functionDuration := stats.NewHistogram(r.Offset.Seconds(), r.Resolution)
+ errorsDuration := stats.NewHistogram(r.Offset.Seconds(), r.Resolution)
// Histogram and stats for Sleep time (negative offset to capture <0
sleep in their own bucket):
sleepTime := stats.NewHistogram(-0.001, 0.001)
if r.NumThreads <= 1 {
log.LogVf("Running single threaded")
- runOne(0, runnerChan, functionDuration, sleepTime,
numCalls+leftOver, start, r)
+ runOne(0, runnerChan, functionDuration, errorsDuration,
sleepTime, numCalls+leftOver, start, r)
} else {
var wg sync.WaitGroup
- var fDs []*stats.Histogram
- var sDs []*stats.Histogram
+ var fDs, eDs, sDs []*stats.Histogram
for t := 0; t < r.NumThreads; t++ {
durP := functionDuration.Clone()
+ errP := errorsDuration.Clone()
sleepP := sleepTime.Clone()
fDs = append(fDs, durP)
+ eDs = append(eDs, errP)
sDs = append(sDs, sleepP)
wg.Add(1)
thisNumCalls := numCalls
@@ -447,14 +455,15 @@
// The first thread gets to do the additional
work
thisNumCalls += leftOver
}
- go func(t int, durP *stats.Histogram, sleepP
*stats.Histogram) {
- runOne(t, runnerChan, durP, sleepP,
thisNumCalls, start, r)
+ go func(t int, durP, errP, sleepP *stats.Histogram) {
+ runOne(t, runnerChan, durP, errP, sleepP,
thisNumCalls, start, r)
wg.Done()
- }(t, durP, sleepP)
+ }(t, durP, errP, sleepP)
}
wg.Wait()
for t := 0; t < r.NumThreads; t++ {
functionDuration.Transfer(fDs[t])
+ errorsDuration.Transfer(eDs[t])
sleepTime.Transfer(sDs[t])
}
}
@@ -490,15 +499,18 @@
result := RunnerResults{
r.RunType, r.Labels, start, requestedQPS, requestedDuration,
actualQPS, elapsed, r.NumThreads, version.Short(),
functionDuration.Export().CalcPercentiles(r.Percentiles),
+ errorsDuration.Export().CalcPercentiles(r.Percentiles),
r.Exactly, r.Jitter, r.Uniform, r.NoCatchUp, r.RunID,
loggerInfo,
}
if log.Log(log.Warning) {
result.DurationHistogram.Print(r.Out, "Aggregated Function
Time")
+ result.ErrorsDurationHistogram.Print(r.Out, "Error cases")
} else {
functionDuration.Counter.Print(r.Out, "Aggregated Function
Time")
for _, p := range result.DurationHistogram.Percentiles {
_, _ = fmt.Fprintf(r.Out, "# target %g%% %.6g\n",
p.Percentile, p.Value)
}
+ errorsDuration.Counter.Print(r.Out, "Error cases")
}
select {
case <-runnerChan: // nothing
@@ -517,7 +529,7 @@
// AccessJSON for json format of access log:
{"latency":%f,"timestamp":%d,"thread":%d}.
AccessJSON AccessLoggerType = iota
// AccessInflux of influx format of access log.
- //
https://docs.influxdata.com/influxdb/v2.1/reference/syntax/line-protocol/
+ //
https://docs.influxdata.com/influxdb/v2.2/reference/syntax/line-protocol/
AccessInflux
)
@@ -538,7 +550,7 @@
// AccessLogger defines an interface to report a single request.
type AccessLogger interface {
// Report logs a single request to a file.
- Report(thread int, time int64, latency float64)
+ Report(thread int, time int64, latency float64, status bool, details
string)
Info() string
}
@@ -584,14 +596,15 @@
}
// Report logs a single request to a file.
-func (a *fileAccessLogger) Report(thread int, time int64, latency float64) {
+func (a *fileAccessLogger) Report(thread int, time int64, latency float64,
status bool, details string) {
a.mu.Lock()
switch a.format {
case AccessInflux:
- //
https://docs.influxdata.com/influxdb/v2.1/reference/syntax/line-protocol/
- fmt.Fprintf(a.file, "latency,thread=%d value=%f %d\n", thread,
latency, time)
+ //
https://docs.influxdata.com/influxdb/v2.2/reference/syntax/line-protocol/
+ fmt.Fprintf(a.file, "latency,thread=%d,ok=%t
value=%f,details=%q %d\n", thread, status, latency, details, time)
case AccessJSON:
- fmt.Fprintf(a.file,
"{\"latency\":%f,\"timestamp\":%d,\"thread\":%d}\n", latency, time, thread)
+ fmt.Fprintf(a.file,
"{\"latency\":%f,\"timestamp\":%d,\"thread\":%d,\"ok\":%t,\"details\":%q}\n",
+ latency, time, thread, status, details)
}
a.mu.Unlock()
}
@@ -602,9 +615,10 @@
}
// runOne runs in 1 go routine (or main one when -c 1 == single threaded mode).
-// nolint: gocognit // we should try to simplify it though.
-func runOne(id int, runnerChan chan struct{},
- funcTimes *stats.Histogram, sleepTimes *stats.Histogram, numCalls
int64, start time.Time, r *periodicRunner) {
+// nolint: gocognit, gocyclo // we should try to simplify it though.
+func runOne(id int, runnerChan chan struct{}, funcTimes, errTimes, sleepTimes
*stats.Histogram,
+ numCalls int64, start time.Time, r *periodicRunner,
+) {
var i int64
endTime := start.Add(r.Duration)
tIDStr := fmt.Sprintf("T%03d", id)
@@ -645,12 +659,15 @@
break
}
}
- f.Run(id)
+ status, details := f.Run(id)
latency := time.Since(fStart).Seconds()
if r.AccessLogger != nil {
- r.AccessLogger.Report(id, fStart.UnixNano(), latency)
+ r.AccessLogger.Report(id, fStart.UnixNano(), latency,
status, details)
}
funcTimes.Record(latency)
+ if !status {
+ errTimes.Record(latency)
+ }
// if using QPS / pre calc expected call # mode:
if useQPS { // nolint: nestif
for {
diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn'
'--exclude=.svnignore' old/fortio-1.27.0/periodic/periodic_test.go
new/fortio-1.28.0/periodic/periodic_test.go
--- old/fortio-1.27.0/periodic/periodic_test.go 2022-04-18 21:54:08.000000000
+0200
+++ new/fortio-1.28.0/periodic/periodic_test.go 2022-04-26 02:16:27.000000000
+0200
@@ -15,8 +15,10 @@
package periodic
import (
+ "bufio"
"math"
"os"
+ "path"
"strings"
"sync"
"testing"
@@ -27,7 +29,8 @@
type Noop struct{}
-func (n *Noop) Run(t int) {
+func (n *Noop) Run(t int) (bool, string) {
+ return true, ""
}
// used for when we don't actually run periodic test/want to initialize
@@ -75,11 +78,13 @@
lock *sync.Mutex
}
-func (c *TestCount) Run(i int) {
+func (c *TestCount) Run(i int) (bool, string) {
c.lock.Lock()
(*c.count)++
+ status := (*c.count)%2 == 0
c.lock.Unlock()
time.Sleep(100 * time.Millisecond)
+ return status, ""
}
func TestStart(t *testing.T) {
@@ -227,12 +232,16 @@
type testAccessLogger struct {
sync.Mutex
reports int64
+ success int64
}
-func (t *testAccessLogger) Report(thread int, time int64, latency float64) {
+func (t *testAccessLogger) Report(thread int, time int64, latency float64,
status bool, details string) {
t.Lock()
defer t.Unlock()
t.reports++
+ if status {
+ t.success++
+ }
}
func (t *testAccessLogger) Info() string {
@@ -268,9 +277,77 @@
if count != expected {
t.Errorf("Access logs executed unexpected number of times %d
instead %d", count, expected)
}
+ if logger.success != expected/2 {
+ t.Errorf("Access logs status success unexpected number of times
%d instead %d", logger.success, expected/2)
+ }
r.Options().ReleaseRunners()
}
+func TestAccessLogFile(t *testing.T) {
+ var count int64
+ var lock sync.Mutex
+
+ c := TestCount{&count, &lock}
+ expected := int64(10)
+ o := RunnerOptions{
+ QPS: -1, // max qps
+ NumThreads: 4,
+ Exactly: expected,
+ }
+
+ for _, format := range []string{"json", "influx"} {
+ dir := t.TempDir()
+ fname := path.Join(dir, "access.log")
+ err := o.AddAccessLogger(fname, format)
+ r := NewPeriodicRunner(&o)
+ r.Options().MakeRunners(&c)
+ count = 0
+ if err != nil {
+ t.Errorf("unexpected error for log file %q %s: %v",
fname, format, err)
+ }
+ res := r.Run()
+ totalReq := res.DurationHistogram.Count
+ if totalReq != expected {
+ t.Errorf("Mismatch between requests %d and expected
%d", totalReq, expected)
+ }
+ if count != expected {
+ t.Errorf("Mismatch between count %d and expected %d",
count, expected)
+ }
+ numErr := res.ErrorsDurationHistogram.Count
+ if numErr <= 1 || numErr >= expected-1 {
+ t.Errorf("Unexpected non ok count %d should be ~ 50%%
of %d", numErr, expected)
+ }
+ numOk := res.DurationHistogram.Count - numErr
+ if numOk <= 1 || numOk >= expected-1 {
+ t.Errorf("Unexpected ok count %d should be ~ 50%% of
%d", numOk, expected)
+ }
+ file, _ := os.Open(fname)
+ scanner := bufio.NewScanner(file)
+ lineCount := 0
+ linesOk := 0
+ linesNotOk := 0
+ for scanner.Scan() {
+ line := scanner.Text()
+ if strings.Contains(line, "true") {
+ linesOk++
+ }
+ if strings.Contains(line, "false") {
+ linesNotOk++
+ }
+ lineCount++
+ }
+ if lineCount != int(expected) {
+ t.Errorf("unexpected number of lines in access log %s:
%d", format, lineCount)
+ }
+ if linesOk != int(numOk) {
+ t.Errorf("unexpected number of lines in access log %s:
with ok: %d instead of %d", format, linesOk, numOk)
+ }
+ if linesNotOk != int(numErr) {
+ t.Errorf("unexpected number of lines in access log %s:
with not ok: %d instead of %d", format, linesNotOk, numErr)
+ }
+ }
+}
+
func TestUniformAndNoCatchUp(t *testing.T) {
var count int64
var lock sync.Mutex
diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn'
'--exclude=.svnignore' old/fortio-1.27.0/stats/stats.go
new/fortio-1.28.0/stats/stats.go
--- old/fortio-1.27.0/stats/stats.go 2022-04-18 21:54:08.000000000 +0200
+++ new/fortio-1.28.0/stats/stats.go 2022-04-26 02:16:27.000000000 +0200
@@ -61,11 +61,17 @@
// Avg returns the average.
func (c *Counter) Avg() float64 {
+ if c.Count == 0 {
+ return 0.
+ }
return c.Sum / float64(c.Count)
}
// StdDev returns the standard deviation.
func (c *Counter) StdDev() float64 {
+ if c.Count == 0 {
+ return 0.
+ }
fC := float64(c.Count)
sigma := (c.sumOfSquares - c.Sum*c.Sum/fC) / fC
// should never happen but it does
diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn'
'--exclude=.svnignore' old/fortio-1.27.0/stats/stats_test.go
new/fortio-1.28.0/stats/stats_test.go
--- old/fortio-1.27.0/stats/stats_test.go 2022-04-18 21:54:08.000000000
+0200
+++ new/fortio-1.28.0/stats/stats_test.go 2022-04-26 02:16:27.000000000
+0200
@@ -34,7 +34,7 @@
var b bytes.Buffer
w := bufio.NewWriter(&b)
c.Counter.Print(w, "test1c")
- expected := "test1c : count 0 avg NaN +/- NaN min 0 max 0 sum 0\n"
+ expected := "test1c : count 0 avg 0 +/- 0 min 0 max 0 sum 0\n"
c.Print(w, "test1h", []float64{50.0})
expected += "test1h : no data\n"
*log.LogFileAndLine = false
@@ -118,9 +118,9 @@
expected := `c1 before merge : count 2 avg 15 +/- 5 min 10 max 20 sum 30
c2 before merge : count 2 avg 85 +/- 5 min 80 max 90 sum 170
mergedC1C2 : count 4 avg 50 +/- 35.36 min 10 max 90 sum 200
-c2 after merge : count 0 avg NaN +/- NaN min 0 max 0 sum 0
+c2 after merge : count 0 avg 0 +/- 0 min 0 max 0 sum 0
mergedC2C1 : count 4 avg 50 +/- 35.36 min 10 max 90 sum 200
-c1 should now be empty : count 0 avg NaN +/- NaN min 0 max 0 sum 0
+c1 should now be empty : count 0 avg 0 +/- 0 min 0 max 0 sum 0
c3 after merge - 1 : count 4 avg 50 +/- 35.36 min 10 max 90 sum 200
c3 after merge - 2 : count 4 avg 50 +/- 35.36 min 10 max 90 sum 200
`
diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn'
'--exclude=.svnignore' old/fortio-1.27.0/tcprunner/tcprunner.go
new/fortio-1.28.0/tcprunner/tcprunner.go
--- old/fortio-1.27.0/tcprunner/tcprunner.go 2022-04-18 21:54:08.000000000
+0200
+++ new/fortio-1.28.0/tcprunner/tcprunner.go 2022-04-26 02:16:27.000000000
+0200
@@ -47,14 +47,16 @@
// Run tests tcp request fetching. Main call being run at the target QPS.
// To be set as the Function in RunnerOptions.
-func (tcpstate *RunnerResults) Run(t int) {
+func (tcpstate *RunnerResults) Run(t int) (bool, string) {
log.Debugf("Calling in %d", t)
_, err := tcpstate.client.Fetch()
if err != nil {
- tcpstate.RetCodes[err.Error()]++
- } else {
- tcpstate.RetCodes[TCPStatusOK]++
+ errStr := err.Error()
+ tcpstate.RetCodes[errStr]++
+ return false, errStr
}
+ tcpstate.RetCodes[TCPStatusOK]++
+ return true, TCPStatusOK
}
// TCPOptions are options to the TCPClient.
diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn'
'--exclude=.svnignore' old/fortio-1.27.0/udprunner/udprunner.go
new/fortio-1.28.0/udprunner/udprunner.go
--- old/fortio-1.27.0/udprunner/udprunner.go 2022-04-18 21:54:08.000000000
+0200
+++ new/fortio-1.28.0/udprunner/udprunner.go 2022-04-26 02:16:27.000000000
+0200
@@ -50,14 +50,16 @@
// Run tests udp request fetching. Main call being run at the target QPS.
// To be set as the Function in RunnerOptions.
-func (udpstate *RunnerResults) Run(t int) {
+func (udpstate *RunnerResults) Run(t int) (bool, string) {
log.Debugf("Calling in %d", t)
_, err := udpstate.client.Fetch()
if err != nil {
- udpstate.RetCodes[err.Error()]++
- } else {
- udpstate.RetCodes[UDPStatusOK]++
+ errStr := err.Error()
+ udpstate.RetCodes[errStr]++
+ return false, errStr
}
+ udpstate.RetCodes[UDPStatusOK]++
+ return true, UDPStatusOK
}
// UDPOptions are options to the UDPClient.
diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn'
'--exclude=.svnignore' old/fortio-1.27.0/ui/static/js/fortio_chart.js
new/fortio-1.28.0/ui/static/js/fortio_chart.js
--- old/fortio-1.27.0/ui/static/js/fortio_chart.js 2022-04-18
21:54:08.000000000 +0200
+++ new/fortio-1.28.0/ui/static/js/fortio_chart.js 2022-04-26
02:16:27.000000000 +0200
@@ -82,7 +82,7 @@
function formatDate (dStr) {
const d = new Date(dStr)
return d.getFullYear() + '-' + pad(d.getMonth() + 1) + '-' +
pad(d.getDate()) + ' ' +
- pad(d.getHours()) + ':' + pad(d.getMinutes()) + ':' +
pad(d.getSeconds())
+ pad(d.getHours()) + ':' + pad(d.getMinutes()) + ':' + pad(d.getSeconds())
}
function makeTitle (res) {
@@ -108,23 +108,32 @@
}
}
percStr += ', max ' + myRound(1000.0 * res.DurationHistogram.Max, 3) + ' ms'
- let statusOk = res.RetCodes[200]
- if (!statusOk) { // grpc or tcp results
- statusOk = res.RetCodes.SERVING || res.RetCodes.OK
- }
const total = res.DurationHistogram.Count
let errStr = 'no error'
- if (statusOk !== total) {
- if (statusOk) {
- errStr = myRound(100.0 * (total - statusOk) / total, 2) + '% errors'
- } else {
- errStr = '100% errors!'
+ if (res.ErrorsDurationHistogram != null) {
+ // Newer simpler calculation when we have the ErrorsDurationHistogram:
+ const statusNotOk = res.ErrorsDurationHistogram.Count
+ if (statusNotOk !== 0) {
+ errStr = myRound(100.0 * statusNotOk / total, 2) + '% errors'
+ }
+ } else {
+ // Old calculation (for older saved data)
+ let statusOk = res.RetCodes[200]
+ if (!statusOk) { // grpc or tcp results
+ statusOk = res.RetCodes.SERVING || res.RetCodes.OK
+ }
+ if (statusOk !== total) {
+ if (statusOk) {
+ errStr = myRound(100.0 * (total - statusOk) / total, 2) + '% errors'
+ } else {
+ errStr = '100% errors!'
+ }
}
}
title.push('Response time histogram at ' + res.RequestedQPS + ' target qps
(' +
- myRound(res.ActualQPS, 1) + ' actual) ' + res.NumThreads + '
connections for ' +
- res.RequestedDuration + ' (actual time ' + myRound(res.ActualDuration
/ 1e9, 1) + 's), jitter: ' +
- res.Jitter + ', uniform: ' + res.Uniform + ', ' + errStr)
+ myRound(res.ActualQPS, 1) + ' actual) ' + res.NumThreads + ' connections
for ' +
+ res.RequestedDuration + ' (actual time ' + myRound(res.ActualDuration /
1e9, 1) + 's), jitter: ' +
+ res.Jitter + ', uniform: ' + res.Uniform + ', ' + errStr)
title.push(percStr)
return title
}
@@ -134,63 +143,94 @@
x: 0.0,
y: 0.0
}]
- const len = res.DurationHistogram.Data.length
- let prevX = 0.0
- let prevY = 0.0
- for (let i = 0; i < len; i++) {
- const it = res.DurationHistogram.Data[i]
- let x = myRound(1000.0 * it.Start)
- if (i === 0) {
+ const dataH = []
+ const dataE = []
+ if (res.DurationHistogram.Count > 0) {
+ const len = res.DurationHistogram.Data.length
+ let prevX = 0.0
+ let prevY = 0.0
+ for (let i = 0; i < len; i++) {
+ const it = res.DurationHistogram.Data[i]
+ let x = myRound(1000.0 * it.Start)
+ if (i === 0) {
// Extra point, 1/N at min itself
- dataP.push({
- x: x,
- y: myRound(100.0 / res.DurationHistogram.Count, 3)
- })
- } else {
- if (prevX !== x) {
dataP.push({
- x: x,
- y: prevY
+ x,
+ y: myRound(100.0 / res.DurationHistogram.Count, 3)
})
+ } else {
+ if (prevX !== x) {
+ dataP.push({
+ x,
+ y: prevY
+ })
+ }
}
+ x = myRound(1000.0 * it.End)
+ const y = myRound(it.Percent, 3)
+ dataP.push({
+ x,
+ y
+ })
+ prevX = x
+ prevY = y
}
- x = myRound(1000.0 * it.End)
- const y = myRound(it.Percent, 3)
- dataP.push({
- x: x,
- y: y
- })
- prevX = x
- prevY = y
- }
- const dataH = []
- let prev = 1000.0 * res.DurationHistogram.Data[0].Start
- for (let i = 0; i < len; i++) {
- const it = res.DurationHistogram.Data[i]
- const startX = 1000.0 * it.Start
- const endX = 1000.0 * it.End
- if (startX !== prev) {
+ let prev = 1000.0 * res.DurationHistogram.Data[0].Start
+ for (let i = 0; i < len; i++) {
+ const it = res.DurationHistogram.Data[i]
+ const startX = 1000.0 * it.Start
+ const endX = 1000.0 * it.End
+ if (startX !== prev) {
+ dataH.push({
+ x: myRound(prev),
+ y: 0
+ }, {
+ x: myRound(startX),
+ y: 0
+ })
+ }
dataH.push({
- x: myRound(prev),
- y: 0
+ x: myRound(startX),
+ y: it.Count
}, {
+ x: myRound(endX),
+ y: it.Count
+ })
+ prev = endX
+ }
+ }
+ if (res.ErrorsDurationHistogram != null && res.ErrorsDurationHistogram.Count
> 0) {
+ // TODO: make a function, same as above with dataH->dataE
+ let prev = 1000.0 * res.ErrorsDurationHistogram.Data[0].Start
+ const len = res.ErrorsDurationHistogram.Data.length
+ for (let i = 0; i < len; i++) {
+ const it = res.ErrorsDurationHistogram.Data[i]
+ const startX = 1000.0 * it.Start
+ const endX = 1000.0 * it.End
+ if (startX !== prev) {
+ dataE.push({
+ x: myRound(prev),
+ y: 0
+ }, {
+ x: myRound(startX),
+ y: 0
+ })
+ }
+ dataE.push({
x: myRound(startX),
- y: 0
+ y: it.Count
+ }, {
+ x: myRound(endX),
+ y: it.Count
})
+ prev = endX
}
- dataH.push({
- x: myRound(startX),
- y: it.Count
- }, {
- x: myRound(endX),
- y: it.Count
- })
- prev = endX
}
return {
title: makeTitle(res),
- dataP: dataP,
- dataH: dataH
+ dataP,
+ dataH,
+ dataE
}
}
@@ -322,6 +362,16 @@
cubicInterpolationMode: 'monotone'
},
{
+ label: 'Error Histogram',
+ data: data.dataE,
+ yAxisID: 'H',
+ pointStyle: 'rect',
+ radius: 1,
+ borderColor: 'rgba(179, 42, 18, .8)',
+ backgroundColor: 'rgba(179, 42, 18, .65)',
+ lineTension: 0
+ },
+ {
label: 'Histogram: Count',
data: data.dataH,
yAxisID: 'H',
@@ -365,7 +415,8 @@
// TODO may need updateChart() if we persist settings even the first time
} else {
chart.data.datasets[0].data = data.dataP
- chart.data.datasets[1].data = data.dataH
+ chart.data.datasets[1].data = data.dataE
+ chart.data.datasets[2].data = data.dataH
chart.options.title.text = data.title
updateChart(chart)
}
++++++ vendor.tar.gz ++++++
