Profiling ~how to improve the performance of a web application ~
Published: 2022-06-29 07:19:38

# Profiling is very important to improve the performance
## What is Profiling?
The meaning of Profiling is that collecting and compiling the information of status of systems performance.

## Why is Profiling important? 

To improve the performance of systems, we have to detect the bottleneck of them.
For example, bottlenecks are N+1 problem of SQL, low-cpu-consuming, no index of tables in Databases, and so on...


![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/sf7xwj6obwj44jyjhp8o.png)

The flow of general web systems is shown above.
Clients (PC, mobile,..) send requests to the system, and the web system processes them.


Throughput and latency are one of the metrics which expresses the performance.
Throughput is the number of requests processed per second.
And latency is the time to process one request.

The throughput varies system to system and the throughput of the whole system is limited by the minimum throughput.


![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/7aokd2c6j3gk1pc3trd4.png)

So, above image shows that the throughput of the system is limited by that of 2.

This teaches us the important thing.
We cannot improve the system by improving the elements which are not the bottleneck.


![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/ttkdaz63695stbygficu.png)

If we improve the element 4, we still cannot make the performance of the system better.

## How to profile?
There are 3 steps for it.
1. load testing with bench markers
2. record logs
3. compiling the logs and calculating the stats

### load testing
We can mock many requests by users with bench markers.

There are many ways to do this, but in this article, I introduce two ways.
One is `ab` command and the other is `k6`.

#### `ab` command
https://github.com/CloudFundoo/ApacheBench-ab
By using this command, we can simply send many requests to one api endpoint and get the simple stats as shown below.

```
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient).....done


Server Software:        nginx/1.22.0
Server Hostname:        localhost
Server Port:            80

Document Path:          /
Document Length:        35644 bytes

Concurrency Level:      1
Time taken for tests:   7.388 seconds
Complete requests:      10
Failed requests:        0
Total transferred:      360070 bytes
HTML transferred:       356440 bytes
Requests per second:    1.35 [#/sec] (mean)
Time per request:       738.809 [ms] (mean) # latency
Time per request:       738.809 [ms] (mean, across all concurrent requests)
Transfer rate:          47.59 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:   728  739  28.5    730     820
Waiting:      727  737  28.0    729     817
Total:        728  739  28.5    730     820

Percentage of the requests served within a certain time (ms)
  50%    730
  66%    730
  75%    732
  80%    732
  90%    820
  95%    820
  98%    820
  99%    820
 100%    820 (longest request)
```

#### k6
`ab` command is also useful but, the requests our system receives are more complicate and the parts of the user story.

So, if you want to simulate more realistic requests, we can use k6.

https://k6.io/open-source/

k6 is one of OSS managing load testing.

We can easily imitate user stories by writing 
scenario files.

### record logs
We have to record system logs for next step.
In this article, I introduce how to record the logs of nginx and mysql.

#### nginx log
We can record api access log by modifying a configuration file `/etc/nginx/nginx.conf` like below.

```
log_format json escape=json '{"time":"$time_iso8601",'
                            '"host":"$remote_addr",'
                            '"port":$remote_port,'
                            '"method":"$request_method",'
                            '"uri":"$request_uri",'
                            '"status":"$status",'
                            '"body_bytes":$body_bytes_sent,'
                            '"referer":"$http_referer",'
                            '"ua":"$http_user_agent",'
                            '"request_time":"$request_time",'
                            '"response_time":"$upstream_response_time"}';
server {
  access_log /var/log/nginx/access.log json;
  listen 80;

  client_max_body_size 10m;
  root /public/;

  location / {
    proxy_set_header Host $host;
    proxy_pass http://app:8080;
  }
}
```

and then we can get an access log file in `/var/log/nginx/` like this.

```jsonl
{"time":"2022-06-29T03:37:40+00:00","host":"172.25.0.1","port":60820,"method":"GET","uri":"/","status":"200","body_bytes":35644,"referer":"","ua":"ApacheBench/2.3","request_time":"6.020","response_time":"6.020"}
{"time":"2022-06-29T03:37:41+00:00","host":"172.25.0.1","port":60830,"method":"GET","uri":"/","status":"200","body_bytes":35644,"referer":"","ua":"ApacheBench/2.3","request_time":"0.982","response_time":"0.981"}
{"time":"2022-06-29T03:37:42+00:00","host":"172.25.0.1","port":60836,"method":"GET","uri":"/","status":"200","body_bytes":35644,"referer":"","ua":"ApacheBench/2.3","request_time":"0.906","response_time":"0.905"}
{"time":"2022-06-29T03:37:43+00:00","host":"172.25.0.1","port":60842,"method":"GET","uri":"/","status":"200","body_bytes":35644,"referer":"","ua":"ApacheBench/2.3","request_time":"1.037","response_time":"1.037"}
{"time":"2022-06-29T03:37:44+00:00","host":"172.25.0.1","port":60848,"method":"GET","uri":"/","status":"200","body_bytes":35644,"referer":"","ua":"ApacheBench/2.3","request_time":"1.025","response_time":"1.025"}
{"time":"2022-06-29T05:55:51+00:00","host":"172.25.0.1","port":60854,"method":"GET","uri":"/","status":"200","body_bytes":35644,"referer":"","ua":"ApacheBench/2.3","request_time":"1.078","response_time":"1.077"}
{"time":"2022-06-29T05:55:52+00:00","host":"172.25.0.1","port":60860,"method":"GET","uri":"/","status":"200","body_bytes":35644,"referer":"","ua":"ApacheBench/2.3","request_time":"0.996","response_time":"0.996"}
{"time":"2022-06-29T05:55:53+00:00","host":"172.25.0.1","port":60866,"method":"GET","uri":"/","status":"200","body_bytes":35644,"referer":"","ua":"ApacheBench/2.3","request_time":"0.995","response_time":"0.994"}
{"time":"2022-06-29T05:55:54+00:00","host":"172.25.0.1","port":60872,"method":"GET","uri":"/","status":"200","body_bytes":35644,"referer":"","ua":"ApacheBench/2.3","request_time":"0.992","response_time":"0.992"}
{"time":"2022-06-29T05:55:55+00:00","host":"172.25.0.1","port":60878,"method":"GET","uri":"/","status":"200","body_bytes":35644,"referer":"","ua":"ApacheBench/2.3","request_time":"0.987","response_time":"0.987"}
```

#### slow query log for mysql
Mysql can record the logs of queries.
We can know many things(how long does it take to execute a query?, how many times is each query called? ...) from that logs.

We can modify the configuration file `/etc/my.cnf` like below.
```
[mysqld]
default_authentication_plugin=mysql_native_password

slow_query_log = 1
slow_query_log_file = /var/log/mysql/mysql-slow.log
long_query_time = 0
```

`long_query_time` is the threshold omitting or not.
If long_query_time is 1, we can record only the logs of the high-time-consuming queries, taking longer than 1 sec.
But, low-time-consuming queries can be also a problem, so first, I recommend you to specify it to 0.
For example, the system calls the same low-cost queries many times and it leads to the increase of latency.

### compiling the logs and calculating the stats
This is the last step of profiling.
#### alp
https://github.com/tkuchiki/alp

`alp` is one of the access profilers.
we can easily check the stats of endpoints like below.
In this case, I only mock requests to the root path and the result show only one line, but if we imitate the user actions and execute load testing, we can get to know which endpoint is the bottleneck for our web system.

```
+-------+-----+-----+-----+-----+-----+--------+-----+-------+--------+---------+-------+-------+-------+-------+--------+-----------+-----------+-------------+-----------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD | URI |  MIN  |  MAX   |   SUM   |  AVG  |  P90  |  P95  |  P99  | STDDEV | MIN(BODY) | MAX(BODY) |  SUM(BODY)  | AVG(BODY) |
+-------+-----+-----+-----+-----+-----+--------+-----+-------+--------+---------+-------+-------+-------+-------+--------+-----------+-----------+-------------+-----------+
|   189 |   0 | 188 |   0 |   1 |   0 | GET    | /   | 0.597 | 10.951 | 160.983 | 0.852 | 0.772 | 0.987 | 6.020 |  0.908 | 35644.000 | 35644.000 | 6701072.000 | 35455.407 |
+-------+-----+-----+-----+-----+-----+--------+-----+-------+--------+---------+-------+-------+-------+-------+--------+-----------+-----------+-------------+-----------+
```

#### mysqldumpslow
`mysqldumpslow` is the profiler for mysql slow queries.
We can identify which query has a bad impact on the system.

## continuous profiling is the key to more improving
In this article, I show you way of thinking about improving the performance of web systems and how to do it.

Finally, I want to say that continuous profiling is very important for more improving.

This is because, after you modify the bottleneck and it works, the bottleneck moves to another part. This shows that we have to improve that part next.


![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/6ijorb77glx02jhm37vy.png)

If you remove the bottleneck, improving the performance of 2, the bottleneck moves to 4.
![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/rhj1ueor26rrbx3owcty.png)

So, in order to improve the performance more, we have to do profiling continuously, and catch up the bottleneck!

Thank you.