Menu
  • ABOUT US
  • WHAT WE DO
  • OUR WORK
    • Close
  • INSIGHTS
  • CONTACT
    • Close
Male Absorbed in reading of a newspaper

Male Absorbed in reading of a newspaper

It’s a report, about Tuxedo. See what I did there?

So the last time we talked about Tuxedo, we talked about the ULOG and TMTRACE. This time around, we’re going to look at a great tool for basic performance profiling.

The great thing with all of the tools we’re looking at, just as with the stuff we looked at in the last post, is that they’re built into the Tuxedo platform. Tuxedo provides a tool out of the box that gives you log files of service execution times at millisecond precision. It’s called txrpt (as per the title for the post) and you enable it for individual servers by specifying CLOPT particular CLOPT settings for your server.

Remember that there are two halves to your CLOPT (command-line) options for a Tuxedo server: general Tuxedo parameters on the left-hand side of the ‘–‘ marker, and server-specific (the ones you code for yourself) on the right hand side of the ‘–‘ marker. We’re specifying general Tuxedo parameters here. The ones we need to set are:

  • -r– to enable txrpt logging
  • -e – to specify the file that stderr will be redirected to for our server

We need both of these together, because txrpt logging is sent to the stderr stream. So we want to control where that txrpt logging goes. By indicating a particular file, we can isolate the performance results we’re interested in.

So, if we were configuring txrpt logging for our old standby, the simpserv server that comes as part of simpapp, the configuration in our UBBconfig file might look like this:

simpserv SRVID=1
SRVGRP=SpeedyServers
MIN=1
MAX=1
CLOPT=”-A -r -e simpapp_txrpt.log — “

Because we’re only specifying standard Tuxedo CLOPT options, we didn’t have to put the “–” marker in our CLOPT options, but it’s there to reinforce exactly what we’re doing there. Whenever we request a service advertised by simpserv now, a record will be logged in simpapp_txrpt.log, giving us start and stop times for that service.

That’s why this is a great feature for profiling performance, but not for production environments: the overhead in disk I/O for a high volume system can be quite high. So in attempting to profile performance, you degrade it horribly.

So far, so good, but how do we get at this delicious information?

The easy way to do this is via the txrpt utility. Given a file like our simpapp_txrpt.log containing txrpt logging (and potentially a date and time range) txrpt will produce a report giving you a low-resolution indication of overall performance. Like this:


[email protected]:~/tux10_0/tuxedo10.0/samples/atmi/simpapp$ txrpt -d 08/09 < toupper_txprt

TOTALS Num/Avg 2/0.00 ——- 2/0.00

SERVICE SUMMARY REPORT
SVCNAME 16p-17p 18p-19p
Num/Avg Num/Avg
————— ——- ——- ——-
TOUPPER 1/0.00 1/0.00
————— ——- ——-
TOTALS 1/0.00 1/0.00

So you get the number of executions in that timeframe, broken down into hourly intervals, and with a handy total. A get a high-level view of what your application usage pattern is over time, at an individual service level. You also get service execution time, down to 100ths of a second. That takes us a long way for not a lot of effort, and may give you everything you need.

If you did want to go for extra credit though, you might be interested to know that the txrpt log file contains execution times at a millisecond level of precision. Here’s a snippet of a txrpt log file:


@CheckExpDate 6529 1014617897 225306420 1014617897 225306421
@UsrAuthenticate 6591 1014617897 225306417 1014617897 225306421
@GetErrorMesg 6366 1014617897 225306423 1014617897 225306424
@GetUsrPermission 6591 1014617897 225306422 1014617897 225306424
@GetMyLocation 6591 1014617897 225306424 1014617897 225306426

The columns in the file, from left to right respectively, are:

  • Service name
  • Process ID
  • Start date (in milliseconds since epoch)
  • Start time
  • End date (in milliseconds since epoch)
  • End time

For each service request, you can get the service execution time in milliseconds by subtracting the start time from the end time. If you want a handy online converter for sanity-checking start and end dates online, you can find an easy to use conversion tool here.

If you were the kind of person who found parsing log files amusing, you could get each individual service call at a millisecond-level resolution, allowing you to get laser precision on what’s going on in your server over time.

Don’t forget though: You’ll be getting all the information logged to stderr for that server in your txrpt file. As well as txrpt logging, you’ll get any error text generated. You only want the lines prefixed by a @

So that’s txrpt. It gives you a great tool to go from no idea to a clear picture of what’s going on inside your application. It’s a great tool to use in pre-production performance profiling, and I have used it with clients before in production environments where they were desperate to get an understanding of how their application was being used.

Next we’ll look at the .TMIB, which is the runtime store of everything Tuxedo knows about everything. We’ll look at how we can get access to that information via SNMP monitoring, and also how we can use a command line tool called the unit driver (ud or ud32) to access this awesome store, and any other service that fulfills some basic requirements.

One Comment

Leave a Reply