DB connection problems? Try a logging datasource!

We’ve been grappling with a number of different problems with our app over the last week. We’ve made many improvements, including several changes to our Spring configs (which I may touch on another day), but we still had a problem where occasionally we ran out of database connections momentarily — no matter how many we had in the pool to start with.

So the other morning I got an itch to start coding while I was waiting for my carpool ride to show up. By the time I got to work, I had a rough draft of something I wanted to try out. It’s a simple logging DataSource. We converted our datasource to one driven by Spring a couple months ago, but we still have a combination of straight JDBC, an old custom in-house ORM tool, and Hibernate. Somewhere among them, we’ve got something occasionally misbehaving.

It’s a pretty simple concept. I decided to extend Spring’s DelegatingDatasourceProxy to make my LoggingDataSource. Configuration is just as simple as changing this:

<jee:jndi-lookup id=dataSourceTarget jndi-name=java:/MyJbossDS/>

to this:

<bean id=dataSource class=com.timshadel.util.LoggingDataSource>
    <property name=targetDataSource ref=dataSourceTarget/>
    <property name=filterPattern value=^(com.timshadel|com.example).*/>
</bean>

<jee:jndi-lookup id=dataSourceTarget jndi-name=java:/MyJbossDS/>

When you turn it on, you might see something like this:

[main] INFO  com.timshadel.util.LoggingDataSource  - Connection request stack trace, filtered by ‘^(com.timshadel|com.example).*’
        com.example.myapp.model.MyClass.determineSomethingImportant(MyClass.java:770)
        com.example.myapp.model.MyClass.updateStatusString(MyClass.java:674)
        com.example.myapp.model.MyClass.loadStatusInfo(MyClass.java:643)
        com.example.myapp.model.MyClass.reloadStatusInfo(MyClass.java:332)
        com.example.myapp.util.helper.LegacyHelper.run(LegacyHelper.java:440)
[main] ERROR com.timshadel.util.LoggingDataSource  - Connection request stack trace, filtered by ‘^(com.timshadel|com.example).*’
        CAUGHT EXCEPTION (java.sql.SQLException): Pretend there’s no more connections.
        com.example.myapp.model.MyClass.determineSomethingImportant(MyClass.java:770)
        com.example.myapp.model.MyClass.updateStatusString(MyClass.java:674)
        com.example.myapp.model.MyClass.loadStatusInfo(MyClass.java:643)
        com.example.myapp.model.MyClass.reloadStatusInfo(MyClass.java:332)
        com.example.myapp.util.helper.LegacyHelper.run(LegacyHelper.java:440)

All of the stacktrace lines have been removed except those that match your pattern. This is helpful to make sure you cut through a typical enterprise Java call stack to only show the calls your code is making. For us that was helpful as a poor man’s way to determine which pieces of our code were using connections frequently. One simple run turned up a few hotspots. If we need to dig in a bit more, perhaps we’ll throw together a simple Ruby script to count how often a given call stack shows up in the log.

Also note, that since this puts the info out to Log4j, you can obviously pull this logging out to a completely separate file, set a different threshold, or use any of the other standard Log4j features to capture this information in a way that’s useful to you.

Finally, please remember that I pulled lots of this together while riding to work. It’s not really meant to be used for anything serious. Please expect warts and problems, but hopefully it’s enough to help get you goin’.

The JSF Burrito, One Year Later

It’s hard to believe that it’s been a year since my “burrito” podcasts on JSF. So what have I done in this last year with JSF? What is my opinion now and how has it changed?

Have you ever skipped out on a movie that was popular? Decided not to see it because it either didn’t fit your taste or didn’t mesh with your life in some other way? I have. I usually look back later on without regret. That’s the way I feel looking back at JSF a year later, but let give you some details.

(more…)

2007 Shake Up

For 2007, I’ve decided to make a few subtle changes to the way I blog and
podcast.

  1. Less Java, more other stuff.
  2. Less rigor, more direct.
  3. More personal.

Less Java, more other stuff. I don’t find that Java captures my main set
of interests any more. I’m going to talk more broadly in both my blog and
the Zdot podcast.

Less rigor, more direct. Up to this point I’ve typically waited to post most substantial things until I’ve had some longer experience. Bloggers like Matt Raible and Ed Gibbs write more stream-of-conscious style. I like the feel it brings, so we’ll see if it fits me in 2007. So don’t be surprised to see posts that reflect my emotions in the moment.

More personal. I’ve avoided most discussion of the more personal sides of life. I’m gonna dabble with extending that a bit more.

While this may not mean big changes for you, I think it’ll free up a few constraints that I’ve put on myself. So out with the old, and in with the new. I’ll talk to you soon.

–Tim