Server traffic statistics
If you are a system admin and you find a lack of information about the Plastic SCM server health here it comes the first step to help you! As I said in the previous blogpost the Channel call log file can help us to monitor the server activity, we will use it.
The Channel call log file can be a complete mess of numbers and letters and sometimes if its size is huge it's really hard to read it, here is where the new "plasticlogstats" tool will help us.
Let's see how it rocks.
What is plasticlogstats?
Plasticlogstats is a tiny tool that is able to read the Channel Call log file, it parses each line getting the relevant information. Once the complete log file is read it generates a small statistics about the PlasticSCM server traffic.
You can sort the stats generated by:
- Received Bytes: Total received bytes on the channel call during the logged time.
- Received Time: Time processing the total received bytes on the channel call.
- Sent Bytes: Total sent bytes on the channel call during the logged time.
- Sent Time: Time processing the total sent bytes on the channel call.
- Method Name: Method name processed.
- Proc time: Process method time.
- Total calls: Total call names processed.
You are also able to filter the total number of results, for example, if you issue the command with this option: "call:5", you will only see the top 5 server calls with more client requests.
Keep in mind that the proc time is parallel time not linear, the Plastic SCM server, obviously, can perform multitude of operations at the same time.
Example
I've been running smoke tests for a while in my local machine, let's check the Channel Call log file generated by the server, I only want to see the top 5 calls with more time spent, it looks like the following:
C:\PlasticSCM\server>type Channel.log.txt | plasticlogstats.exe proc:5
50688 lines read
proc
Method Recv (Mb) Recv (min) Sent (Mb) Sent (min) Proc (min) Count Des (min) Meth (min) Ser (min) Zip (min)
CheckIn 1,06 0,00 0,60 0,00 1,08 898 0,00 1,06 0,01 0,00
CreateRepository 0,27 0,02 0,25 0,03 0,76 532 0,00 0,53 0,03 0,04
GetChangesetTree 0,29 0,00 0,22 0,00 0,61 595 0,00 0,50 0,07 0,01
CalculateMerge 0,44 0,00 0,37 0,00 0,52 237 0,00 0,50 0,02 0,00
GetBranchInfoByName 0,61 0,00 0,67 0,00 0,34 1278 0,00 0,26 0,03 0,02
Total Recv 127,52 Mb
Total Recv 0,03 min
Total Sent 32,50 Mb
Total Sent 0,03 min
Total Call 8815
Total Time 5,16 min
Total Deserialization 0,00 min
Total Method call 4,28 min
Total Serialization 0,22 min
Total Zip 0,11 min
root@debian:~/proxy# cat ChannelCall.log.txt | ./plasticlogstats -machine-method method:10
1764 lines read
method
Method Recv (Mb) Recv (min) Sent (Mb) Sent (min) Proc (min) Count Des (min) Meth (min) Ser (min) Zip (min)
192.168.1.65 - GetObjectsData 0.02 0.00 1.36 0.00 0.06 15 0.00 0.05 0.00 0.00
192.168.1.59 - GetObjectsData 0.01 0.00 0.01 0.00 0.01 6 0.00 0.00 0.00 0.00
192.168.1.54 - GetObjectsData 0.62 0.00 613.09 1.68 4.41 346 0.00 4.31 0.01 0.00
192.168.1.53 - GetObjectsData 1.95 0.00 881.66 1.64 0.92 1397 0.00 0.66 0.03 0.00
Total Recv 2.60 Mb
Total Recv 0.01 min
Total Sent 1496.12 Mb
Total Sent 3.32 min
Total Call 1764
Total Time 5.40 min
Total Deserialization 0.00 min
Total Method call 5.03 min
Total Serialization 0.04 min
Total Zip 0.00 min
root@debian:~/proxy# cat ChannelCall.log.txt | ./plasticlogstats -machine-only method:10
1764 lines read
method
Method Recv (Mb) Recv (min) Sent (Mb) Sent (min) Proc (min) Count Des (min) Meth (min) Ser (min) Zip (min)
192.168.1.65 0.02 0.00 1.36 0.00 0.06 15 0.00 0.05 0.00 0.00
192.168.1.59 0.01 0.00 0.01 0.00 0.01 6 0.00 0.00 0.00 0.00
192.168.1.54 0.62 0.00 613.09 1.68 4.41 346 0.00 4.31 0.01 0.00
192.168.1.53 1.95 0.00 881.66 1.64 0.92 1397 0.00 0.66 0.03 0.00
Total Recv 2.60 Mb
Total Recv 0.01 min
Total Sent 1496.12 Mb
Total Sent 3.32 min
Total Call 1764
Total Time 5.40 min
Total Deserialization 0.00 min
Total Method call 5.03 min
Total Serialization 0.04 min
Total Zip 0.00 min
Reading the stats
As you can see the top 1 operation is the check-in. The check-in operation is executed several times in every single smoke test so it's logically the first one in our list. Wow 898 checkin calls from a single client and only a couple of minutes!
The total amount of client calls has been 8815, not bad but someday I'll post the server stress tests results, the numbers are amazing!
We can check the network traffic, for this small test the server has received 127.52 Mb of data and it has sent 32.50 Mb, you can also review the time spent to do that. Usually the Plastic SCM metadata volume is not high, it tends to be small so generally the network transfer rate is defined by your repository size.
Finally we can take a look to the deserialization, serialization and zip times, maybe this parameters are more internal but they are also interesting. The deserialization value is the time spent by the server in reading the network objects and transform them into memory objects, the serialization is the opposite. The zip time is the time that the server takes to compress the objects to finally send them through the network. For example, the method "GetChangesetTree" used inside the update operation is going to spend more time than other methods in the serialization since it has to transform a great number of objects to be sent through the network.
Besides that you can use the "-machine-only" and "-machine-method" to check the stats by client machine.
With the "-machine-method" parameter you will be able to group the calls by machine, and then see the stats by method name. With the "-machine-only" you will view the stats regarding the clients, only client info is shown.
Where can I find plasticlogstats?
The plasticlogstats tool will be included in the incoming 4.0 and 4.1 release.
0 comentarios: