🚀 [Feature]: Log show lowerst time-unit that makes sense [#2258] #2561
Comments
|
gin-gonic/gin defaultLogFormatter https://github.com/gin-gonic/gin/blob/62b50cfbc0de877207ff74c160a23dff6394f563/logger.go#L143 used %13v on params.Latency. which looks like: | 4.333µs |
| 1.133916ms |
| 1.000057458s |gofiber/fiber/middleware/logger uses %7v on TagLatency.latency | 4.834µs |
| 1.136834ms |
| 1.000066333s |13 chars seems to be better. Otherwise gofiber/fiber/middleware/logger behaves the same as the default Gin logger. I will add a test and change the formating of the string to %13v in a PR. |
|
@MartinHotmann #2569 should resolve padding, but current code already formats like gin defaultLogFormatter. |
|
@sixcolors thanks for your response! For me it was never about the padding, but thanks for that - I appreciate it. For me it was about: Fiber never shows any " (you can see this in the example I provided above) But here again. I will provide a log from fiber when calling a static site: Please note, that the page The first time I call it, it takes a little longer, but the other times are much faster, but still it shows Since we are already talking: is it possible to pass that string/variable to the template? Thanks in advance :) |
|
It should be doing what you want. Let me invesitgate further. |
|
@MartinHotmann I can't seem to replicate your issue with logging the latency. ┌───────────────────────────────────────────────────┐
│ Fiber v2.48.0 │
│ http://127.0.0.1:8003 │
│ (bound on host 0.0.0.0 and port 8003) │
│ │
│ Handlers ............. 4 Processes ........... 1 │
│ Prefork ....... Disabled PID ............. 64375 │
└───────────────────────────────────────────────────┘
22:13:06 [127.0.0.1] 200 - 1.218709ms GET /
22:13:08 [127.0.0.1] 200 - 1.282416ms GET /
22:13:08 [127.0.0.1] 200 - 1.254958ms GET /
22:13:09 [127.0.0.1] 200 - 1.389375ms GET /
22:13:09 [127.0.0.1] 200 - 105.792µs GET /
22:13:10 [127.0.0.1] 200 - 144.666µs GET /
22:13:10 [127.0.0.1] 200 - 140.709µs GET /
22:13:11 [127.0.0.1] 200 - 146.792µs GET /
22:13:12 [127.0.0.1] 200 - 1.288667ms GET /
22:13:11 [127.0.0.1] 200 - 1.001153959s GET /
22:13:12 [127.0.0.1] 200 - 1.000757084s GET /
22:13:13 [127.0.0.1] 200 - 1.00119775s GET /here is the sample app I used: package main
import (
"math/rand"
"time"
"github.com/gofiber/fiber/v2"
"github.com/gofiber/fiber/v2/middleware/logger"
)
func main() {
server := fiber.New()
server.Use(logger.New(logger.Config{
Format: "${time} [${ip}] ${status} - ${latency} ${method} ${path}\n",
}))
server.Static("/", "../static", fiber.Static{
Compress: true,
})
durations := []time.Duration{time.Nanosecond, time.Microsecond, time.Millisecond, time.Second}
rand.Seed(time.Now().UnixNano())
server.Get("/", func(c *fiber.Ctx) error {
// randomly sleep for either 1ns, 1μs, 1ms, or 1s
duration := durations[rand.Intn(len(durations))]
time.Sleep(duration)
return c.SendString("Hello, World!")
})
server.Listen(":8003")
}What version of fiber are you using and on what platform? What is your logger config? To display the latency measured by the logger middleware on your website, you would need to implement an approach that involves tracking the latency externally. Due to the nature of the HTTP request-response cycle, directly measuring and displaying the exact latency within the same request and response is paradoxical. One approach to achieving this is by keeping track of the request and its latency on the server side and then making a subsequent request, perhaps using JavaScript's Fetch API, to retrieve and display the tracked latency on your website. Alternatively, integrating with external monitoring or analytics systems, such as Prometheus or StatsD, can provide a more comprehensive and accurate solution for measuring and visualizing latency and other performance metrics over time. These systems allow you to gather and analyze data without impacting the main application's performance, ensuring a scalable approach to monitoring your application's performance metrics. As a simplified and hacky demonstration, you could implement an average response time tracking mechanism similar to the following. However, it's important to note that this approach serves more as an illustrative starting point rather than a robust solution. One of its significant limitations is that it calculates a running average since the start of the server without a defined window, which can result in skewed results and may not provide meaningful insights into the actual request latencies: [...]
type customWriter struct {
stdout io.Writer
avgLat time.Duration
count int
mux sync.Mutex
}
func (d *customWriter) Write(p []byte) (n int, err error) {
// write to stdout
n, err = d.stdout.Write(p)
if err != nil {
return n, err
}
// figure out the average latency and track that in a global variable
// this is a hacky way to do it, but it works
// Get latency from Format: "${time} [${ip}] ${status} - ${latency} ${method} ${path}\n",
regexp := regexp.MustCompile(`([0-9]+(\.[0-9]+)?(ns|µs|ms|s))`)
matches := regexp.FindStringSubmatch(string(p))
if len(matches) > 0 {
latency, err := time.ParseDuration(matches[1])
if err != nil {
return n, err
}
d.mux.Lock()
d.avgLat = ((d.avgLat * time.Duration(d.count)) + latency) / time.Duration(d.count+1)
d.count++
d.mux.Unlock()
}
return n, nil
}
func main() {
server := fiber.New()
customWriter := &customWriter{
stdout: os.Stdout,
}
server.Use(logger.New(logger.Config{
Format: "${time} [${ip}] ${status} - ${latency} ${method} ${path}\n",
Output: customWriter,
}))
[...]
server.Get("/", func(c *fiber.Ctx) error {
return c.SendString("Hello, World! The Average Latency is: " + customWriter.avgLat.String())
})
server.Listen(":8003")
}Hope that helps. Considering the complexities and limitations of measuring and displaying request latencies within the same response, you might find it more effective to explore alternative approaches. Perhaps even creating a dedicated middleware designed specifically for tracking and presenting latency data could provide a more accurate and maintainable solution for showcasing request latencies on your website. |
|
@MartinHotmann. If you aren't aware, Fiber offers a built-in middleware called monitor that might partially serve your purpose. It's worth exploring this middleware as it provides monitoring functionalities that could potentially enhance your ability to track and display latency and other metrics on your website. |
|
There's also the |
You are right - this did the trick! I was using: So it seems like that the default config is not providing the wanted output. Source: https://docs.gofiber.io/api/middleware/logger/#default-config (but it seems this is not the default config?) And also thanks for #2569 this should get rid, of the not properly formatted logs. @gaby thanks for the recommendation, but I guess this is a little overkill for my small project. Will look into anyway! |
|
@the-hotmann It seems I've figured out the issue. When you utilize the default formatter, the code within the tags.go file are not utilized. Instead, the output functions located in logger.go are used. It seems this was done for the purpose of adding colors; the duplication seems somewhat unnecessary and I may refactor the code at a later time. For now I have submitted a pull request to address the issue in PR #2580. |
|
Thanks! I appreciate the fix :) Do we get 2.48.1 as a quickfix? 👀 |
|
will release end of this week or next week, depends on the open pull requests and the progress there |
Feature Description
Refering to #2258
When I check my Fiber logs, it instead of
0snow always shows:xms.This is better, as it is more precise, but I really would recommend it, if Fiber (just like Gin) would show he smallest unit that makes sense:
1.423s456.ms18.374µs432nsFiber, will (in my expirience) never show
µs&ns, even though I am relly sure, it does not always take exactly 1ms ;)Additional Context (optional)
The log looks like this for me (IP replaced with
123.123.123.123):Also the responsetime of the very same request fluctuates between
0sand5ms- which in my case is very high and other WebFrameworks do not do.Since I migrate to Fiber I hope that these little things will be fixed somewhen, it is not urgent, but also the Benchmarks (where Fiber always outperforms others) are ATM not matching my real-life expirience, of beeing any faster than Gin for example.
Maybe they just apply, when a big number of requests are triggered.
Code Snippet (optional)
No response
Checklist:
The text was updated successfully, but these errors were encountered: