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:

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:


kevinpowe@yamamoto:~/tux10_0/tuxedo10.0/samples/atmi/simpapp$ txrpt -d 08/09 < toupper_txprt

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.

I drive a 2004 Holden Astra hatch. It is not a glamorous or luxury car. I will never drive it down winding forest roads or through oil-black rainslick streets while my eerily coiffed European model wife sleeps, elegantly arranged next to me. (cue sweeping strains of classical music) But it does me just fine, thank you very much. I like the car so much that, after someone killed my last black Holden Astra, I brought pretty much the same car again. Then someone tried to kill this one in Melbourne, but that’s another story entirely

Recently, my car was kind enough to suggest that a new fuel pump might be in order, by way of killing the old one. While I was procrastinating over getting the car fixed, my partner was kind enough to let me do a substantial amount of driving in her car. I’ve driven her car around a number of times before, as you do in regular life. But this was a long enough stretch to acclimatise to her car as my regular driving experience. And it is a neat, practical car – it’s compact, corners fantastically, has more pick-up than mine in first gear, and has awesome cup-holders. And for coffee freaks, cup-holders are important.

But the experience when I got my car fixed was like driving a completely new car again. I saw my car through the eyes I had when I first bought it, and remember why I love the act of driving it, and why its been a great companion relocating interstate twice. Why I like sitting a little closer to the road, how comfortable the seats really are, how the interior design is put together in a way to melt away when you’re driving at night, and the sense of space and comfort it gives, even though it’s a smallish four-door hatch.

The lesson for myself here, which you’re welcome to take away too if it resonates, is this: when we use products, we often assume the positive parts of the experience as a given, and they become transparent – it’s difficult to appreciate them on a day to day basis. We can still see the negative though, and focus on that. It’s only when we move away from a product that the positive becomes clear, often by contrast. So I’m going to do my damnedest to remember that, if the only feedback for something is negative, it doesn’t necessarily mean it’s bad, if it’s still doing its job and being used widely.

It could just mean that the good stuff has become transparent.

Things have been a little quiet around here, my dear imaginary audience, and for that I apologise profusely. I’ve been finding most of my spare time taken over by a pet programming project which I’m perched on the edge of revealing and quite excited about, despite its tiny scope. (more on that soon, I promise!)

As I find myself for the first time in quite a long time on a plane without the girl as company, it seemed high time to furnish you with a blog post. Post-production has taken a LOT longer than I’d hoped in making this available post-flight, but here we are finally.

My last post was about the general principle of reading the log files, so I thought I’d jump into specifics about where to find useful information with Tuxedo. I had intended this to be one complete post, but due to the wonderful fractal quality of explaining things, I’ll need to break this up into a series.

For those of you unfamiliar with Tuxedo, this post is unlikely to have much interest or benefit. Before we possibly part ways though, I’ll take a moment to explain exactly what Tuxedo is, as it’s somewhat rarified knowledge nowadays, but the market seems to be pushing to make it and similar products popular again. From my less cynical vantage point, it looks at the moment like a healthy step backwards from making the solution to EVERYTHING a web service, or SOA.

So what is Tuxedo?

Tuxedo is what’s referred to as an Online Transaction Processing system. (OLTP, if you’re looking for a sexy acronym for your new tattoo) It’s also commonly referred to as a Transaction Processisng system, but that’s a shorter version of the same thing fundamentally.That means that it processes a huge volume of small operations. Because those operations are things that need to either work or fail consistently, we call those transactions. Transactions can be anything from processing a credit card charge, to updating the location of a package in transit for delivery, to transferring funds between accounts.

One of the big advantages of Tuxedo in particular is that it offers clients a set of available services, each with a unique name. Those services can be provided by a large, complex group of interconnected machines, or all of those services can be provided by one single machine. Clients don’t know and don’t care about the exact location of an available service. They connect to a central point, and request services by name. The exact process that provides that service is unknown to them, which lets you be much more flexible with how you structure the internals of a Tuxedo application.

Because OLTPs are so good at processing these high volumes of transactions (and typically have other technological benefits that make them attractive) they’re used by some big companies, often in preference to newer, ‘cooler’ technology like web services or JEE applications, for example. Just to drop two names, last time I heard both American Express and Fedex were Tuxedo users.

Thus ends the general part of the post. Thanks for listening!

Now… how to get more useful information out of Tuxedo?

ULOG

The pimp-mack-super-daddy of information in Tuxedo is the ULOG file. This is where Tuxedo logs all of its own information, and also where any calls to the function write data. if you’re having problems with Tuxedo, this should always be your first port of call. By default, the ULOG file lives in the directory pointed to by the APPDIR environment variable. If you haven’t set APPDIR explicitly, then the ULOG file lives in the same directory as your TUXCONFIG file.

The ULOG file is actually a series of files, one for each day. The format of ULOG files is as below:

ULOG.mmddyy

where mm is the current month, dd is the current day of the month, and yy is the last two digits of the current year. Frustratingly, that leaves those files just short of sorting perfectly in chronological order. But I’m sure there’s a solid historical American reason for that convention, possibly involving orange cheese. As it stands, they’ll sort fine inside one year.

You can also control the location of ULOG files with the ULOGPFX environment variable. If you want to keep log files somewhere specific, you can specify a directory and filename like the following:

export ULOGPFX=/var/log/tuxedo/VERYSPECIAL

With that convention, you’d get a file created on the 12th of April 2009 called /var/log/tuxedo/VERYSPECIAL.041209.

Every message that Tuxedo places in the ULOG file comes from a message catalog. You can find a starting point for the Tuxedo message catalog reference here. Nine times out of ten, if you have some cryptic message in the ULOG file, the message catalog documentation will shed some light on what’s going on, or at least give a hint of the general area of the problem. Unfortunately, one time out of ten, you’ll get a “Contact BEA Support” message, or a repeat of exactly what you’re seeing in the ULOG file.

One thing that gets overlooked sometimes when troubleshooting behaviour between a client and server is that the client gets their own ULOG file too. The same variables (APPDIR and ULOGPFX) control where it’s created. Oftentimes, especially with connectivity issues or situations where nothing appears to be happening in the Tuxedo application itself, it’s the logs for the client and server together that form the complete picture.

TMTRACE: The Firehose

Now, the standard information in the ULOG file is often enough to solve simple problems. But, sometimes a problem comes along that’s complex enough that you need more. That’s where tmtrace comes in. It’s a facility in Tuxedo that allows you to provide more detailed information about what’s happening at runtime. It’s a very lightly documented feature, and I have to confess that my understanding of it borders on hoodoo. But I’ve found that even that hoodoo level of understanding is tremendously useful.

It works on a trace specification, which essentially allows you to specify three things:

• A trace category, identifying what area of Tuxedo you want more information on.
• Where you want information to go, which has to be the ULOG file.
• Whether you want your particular service request to ‘dye’, meaning that all work done as part of your service request will use the same trace configuration you’ve specified, or just use the current configuration for that server.

I’ll explain each of those in a little more detail to shed some light:

The trace category can be as broad as a number of key areas that the documentation provides, or specific as an individual function. Personally, I tend to use the broader areas that are documented, because it means not having to adjust trace specifications constantly. I’m a big fan of the firehose.

The documented categories are:

• atmi – Specific ATMI functions
• iatmi – work done implicitly on behalf of an ATMI function, or as part of administration. This is a superset of the atmi category.
• xa – work done to manage XA transactions
• trace – work done related to managing trace functionality

The first three areas tend to be the most useful. In fact, you can just set the firehose to pulverize, use ‘*’, and get everything.

In terms of destinations for trace information, there’s an exciting new change with the more recent versions of Tuxedo: you can now specify utrace as a destination, which can send trace information to a custom destination. That was certainly new to me. The documentation is a little unclear on the specific limits of utrace, and seems to indicate that it can only be used with tmtrace information.

Now, dyeing behaviour. I can set trace configuration as surgically as on a server by server basis. So individual processes can have either their own or no current trace configuration. They could be the quiet, introspective server that lives next door.

Because Tuxedo works on the concept of services, the work done in order to process my service call to process a credit card charge might not be as simple as I think. The one server that takes my service call might make two service calls of its own. One of those service calls might turn into another three service calls. The flow could end up looking like this:

If we only want to use tracing for a specific flow of logic, to find out what happens with the full flow of processing, using dye allows us to follow processing not just for server A (where we’d set trace) but all the way through to servers D, E and F.

You can set trace configuration either using the TMTRACE environment variable, or using changetrace from inside tmadmin. The simplest way to enable tracing is flick everything on, using changetrace on, or you could just enable tracing for ATMI functions and send trace info to the ULOG file, as follows:

changetrace "atmi:ulog"

For more information on trace specification formats, the best reference is the documentation for tmtrace.

So that’s the ULOG file, and TMTRACE. Both of these together will form the first and and best line of investigation when something is going wrong with your Tuxedo application. Typically, your ULOG file is kind enough to provide some idea of what is going wrong with your application without any additional work. If not, you can coax more useful information out via TMTRACE.

Next up, we’ll have a look at txrpt, and the .TMIB service in Tuxedo – both great tools that provide us with the basics of performance and runtime monitoring in Tuxedo.

I don’t claim to be a Top Gun consultant by any stretch of the imagination. Sadly, the Val Kilmer of IT consulting (whoever that might be) is unlikely to offer to let me ride his tail any time. (seriously, how could you deliver that dialogue with a straight face? Even in the 80s?)

But, I have gotten a lot of wins on client site by following one deceptively simple rule: read the log files. When strange things are happening intermittently, the first and best port of call is the log files for the system you’re debugging. Now, I don’t claim to be a genius in having discovered this rule. But it’s somewhere between surprising and depressing the number of times I’ve worked with really smart people and get a blank stare when I’ve asked ‘what do the log files say?’

And it’s wisdom I’ve come by the hard way myself. One of my first jobs was installing a HRMS system on client sites, and while troubleshooting a major hiccup with an install on client site, I was on the phone to our guru in the office. He asked if I’d checked the log files. I realised… I didn’t even know where the log files were. It turned out, if I’d checked them, I would have saved myself and the client a lot of grief, including a day’s work restoring from an old backup.

Log files are the forensic evidence of technical troubleshooting. And if we want to be the Grissoms of our own CSI, then there’s a few pointers it’s worth following.

Know where your log files are

It might sound like an obvious rule of thumb, but cases often have more than one crime scene, and the most important one might not be particularly obvious. You might be driving requests to an application through an interface that’s not giving you much more than an ‘Error occurred’, but chances are a log file somewhere is dutifully scribing reams of text about the problem that’s occurring.

For JEE applications, for example, you’ve got your default server log file, and application-specific log files at the very least. In the case of WebLogic Server, you’ve got your domain log file as well, and if you’re having problems with your back-end database, then the real answer might be in XA trace logs on your database server.

Once you’ve established where your log files are, understand where you can go to get additional context on problems that are occurring, as well. If you’re fortunate enough to have a unique message id associated with the error that’s occurring, understand where to find the specific documentation for your product stack so you can get more information on that specific error. And if that doesn’t give you a satisfactory answer, your next step might be a good solid Googling.

Don’t search on text strings

If there’s one thing my years of intensive crime show watching have taught me, it’s that forensics are all about understanding the problem that’s there, not the one you think you have. Almost invariably, if you search on a text string to try and troubleshoot, you’ll miss something.

A bit part of troubleshooting is understanding specific problems or errors in the context of anything else that might be happening at runtime, as well. So searching for keywords or text strings will catapult you past pages of logging that may contain that vital clue that will crack the case.

Look for patterns

Individual error messages by themselves may not mean much, but combining error messages and application behaviour can be a telling sign. It could well be that a specific server-side component is causing database connection leaks. Or, maybe it’s accessing a particular page in your web application that is causing all of those JNI crashes.

Understanding the patterns of behaviour in an application (if you’re lucky enough to have several days of log file information to debug from) can be crucial to finding the core problem.

Know how to turn on the fire hose

Once you’ve gotten a fairly clear idea of what the problem is, knowing how to configure more verbose levels of debug information can be very important. Keeping a reference handy on the debug switches supported for the product you’re troubleshooting is never a bad idea. In the case of WebLogic Server, for example, from WebLogic Server 9.0 onward, a number of configurable debug switches can be selected from inside the Administration Console. Handy! (it’s important to note though that these switches are far from the complete list you can use)

I’d like to talk about some rules of thumb that I think are good to follow to make a log file to be proud of as an application developer, and also how to troubleshoot some specific technologies, but that’s enough for now. I’ll come back to the other stuff.

Got any log file experiences? Bizarre error messages involving processes being sent insane by zombie children or the like? Times where you’ve saved the day and come out a hero, all thanks to a few choice log file messages? Share them in the comments, or just drop me a line and let me know what you think!

Hello! Once again, profuse apologies for the silence. Moving to Perth, technical issues on the project I’m working on, and a crunch for deadlines for one of the products I’m involved in developing has meant that things have been a little disrupted for a while. But I’ve been thinking big thoughts… mostly about Tuxedo and ALSB at the moment. They’re a rarified taste, but I’ll try to pass on some of what I’ve been dealing with in time.

For the moment though… now that I’ve found my notebook again, here’s a post I’ve had queued for a little while now and have been meaning to get around to.

This is a much shorter post than the lengthy screeds on the material and delivery aspects of training, for three key reasons.

• One, I’m trying to learn my lesson about long posts.
• Two, I have less to say about this aspect of training delivery.
• Three, admittedly it’s the aspect of training you have the least amount of control over.

Fundamentally, a good training venue is one that can keep the trainer mobile, and the students awake. And, given that keeping the instructor mobile is about keeping students awake, it fundamentally boils down to keeping the students awake. The rest largely takes care of itself.

Air conditioning and lighting

There’s no greater recipe for sending students off to sleep than a warm, dimly lit room. Except maybe if you handed out pillows first. A good training venue should have reliable air conditioning. Without creating a welcoming environment for the penguins, err on the side of cooler. Also, bright lighting helps it feel less like Sleepytown.

Snack time!

It’s understandable that training venues often don’t allow students to eat food, given the mess it makes. But, even with the possibility of spills, good training venues let students (and the trainer) have drinks in the room. Water helps concentration, and coffee and tea helps students (and you as the trainer) fight through the tiredness as the week draws on.

Also, while sugar has a crash to go with its rush, the better training venues provide bowls of lollies for students to nibble on. Lollies like Minties or Fantales give students sugar to keep them awake, something to do besides listening, and something to eat that doesn’t make a mess.

Remote mouse and projector

If you can stay mobile as a trainer, you’ll be more awake and alert, and you’ll be able to be more engaging and dynamic in your delivery as a result. Being able to move around the room lets you interact with students directly – to be more dramatic, and vary how your delivery is physically arranged. But that requires two things.

First and foremost, the venue should use a projector to display the slides being talked to at the front of the room. That way, you can address the course material while still moving about. A laser pointer can help here as well, but that’s a matter of personal preference.

Second, some sort of remote to be able to interact with the PC displaying the slideware. I’ve used both a radio mouse and a laptop remote to good effect in the past. Being able to interact with the slideware remotely stops you having to continually dash back to press a key to move between slides – it lets your presentation flow more smoothly.

The other big bonus from having the slides projected to the front of the room is that it gives everyone a shared, central focal point, rather than staring at individual monitors.

Internet-capable, well-spaced PCs

The student’s PCs should, in the interests of comfort, be spaced far enough apart that students aren’t cramped together. A gap the size of a monitor between student’s monitors is a good starting rule.

Also, and this is a bit of a divided topic, the students should have internet access, and be able to use their PCs while you’re delivering training. It can mean that student’s minds will wander the internet rather than listen to you, but students are more likely to stay awake if they’re not forced into a passive role. I’ve delivered training for a partner where the students PCs were turned into passive broadcasters of the training material while the trainer is presenting, and it’s not great. It makes staying focused and awake more difficult for students, not to mention preventing them from tinkering or playing catchup with exercises.

Well, that’s it for thoughts on training venues, and training overall. Hope you’ve enjoyed the posts, as slow as they’ve been to arrive. Here’s to a better posting schedule in 2009 now that I’m settled down!