A couple of days ago, I posted on how I was monitoring memory usage on a recently upgraded CF8 server. I was seeing a quite a bit of memory being tied up in the tenured generation portion of the JVM Heap that would steadily rise all day.
Since there were so many dramatic changes between ColdFusion MX 7 and ColdFusion 8, I wasn't sure if this really indeed was a "problem" or simple a difference in behavior. Afterall once the load on the server would reduce in the evening I'd see the tenured generation usage drop back down to an acceptable and more expected value.
Because this did have me concerned, I kept digging around server logs to see if I could find any clues to why I was seeing the memory usage climb. I then noticed that the ColdFusion8/runtime/logs/coldfusion-out.log files were getting tons and tons of activities. After opening up the log files, I noticed I had tons of errors like the following:
2007-12-12 15:57:27 SeeFusion: ----Statement[755940]: exception start ----
2007-12-12 15:57:27 SeeFusion: java.sql.SQLException: [Macromedia][SQLServer JDBC Driver]Auto-generated keys were not requested, or the SQL was not a simple INSERT statement.
at macromedia.jdbc.base.BaseExceptions.createException(Unknown Source)
at macromedia.jdbc.base.BaseExceptions.getException(Unknown Source)
at macromedia.jdbc.base.BaseStatement.getGeneratedKeys(Unknown Source)
at com.seefusion.wc.getGeneratedKeys(wc.java:548)
at coldfusion.server.j2ee.sql.JRunStatement.getGeneratedKeys(JRunStatement.java:415)
at coldfusion.sql.Executive.getRowSet(Executive.java:487)
at coldfusion.sql.Executive.executeQuery(Executive.java:1229)
at coldfusion.sql.Executive.executeQuery(Executive.java:1008)
at coldfusion.sql.Executive.executeQuery(Executive.java:939)
at coldfusion.sql.SqlImpl.execute(SqlImpl.java:325)
at coldfusion.tagext.sql.QueryTag.executeQuery(QueryTag.java:831)
at coldfusion.tagext.sql.QueryTag.doEndTag(QueryTag.java:521)
and:
2007-12-12 15:57:28 SeeFusion: ----Statement[755940]: exception end ----
2007-12-12 15:57:28 SeeFusion: ----Statement[755954]: exception start ----
2007-12-12 15:57:28 SeeFusion: java.sql.SQLException: [Macromedia][SQLServer JDBC Driver][SQLServer]Incorrect syntax near '0'.
at macromedia.jdbc.base.BaseExceptions.createException(Unknown Source)
at macromedia.jdbc.base.BaseExceptions.getException(Unknown Source)
at macromedia.jdbc.sqlserver.tds.TDSRequest.processErrorToken(Unknown Source)
at macromedia.jdbc.sqlserver.tds.TDSRequest.processReplyToken(Unknown Source)
at macromedia.jdbc.sqlserver.tds.TDSRequest.processReply(Unknown Source)
at macromedia.jdbc.sqlserver.SQLServerImplStatement.getNextResultType(Unknown Source)
at macromedia.jdbc.base.BaseStatement.commonTransitionToState(Unknown Source)
at macromedia.jdbc.base.BaseStatement.postImplExecute(Unknown Source)
at macromedia.jdbc.base.BaseStatement.commonExecute(Unknown Source)
at macromedia.jdbc.base.BaseStatement.executeInternal(Unknown Source)
at macromedia.jdbc.base.BaseStatement.execute(Unknown Source)
at com.seefusion.wc.execute(wc.java:291)
It was pretty evident at this point that I was having issues with my SeeFusion JDBC Wrapper. We were using a very old version of SeeFusion in production (v3.3) which was written long before CF8 was released.
The problem wasn't immediately noticed because the errors that are thrown are silent errors. The site was working as expected, it's just that the SeeFusion JDBC Wrapper isn't always able to communicate properly with the new drivers.
So, last night I disabled the SeeFusion JDBC Wrapper and re-started the services (just to make sure I cleared out any possible leaks that might have occurred.)
I'm happy to report that the server is running great today. I'm actually seeing less overall memory being used than I was under CF7. Since my traffic pattern has been pretty much the same today, I believe I'm safe assuming this resolved the problem.
After contacting SeeFusion support and talking with Patrick Quinn, this is a known problem with older versions of SeeFusion when using the new MSSQL 2005 drivers in CF8.
I think the reason the errors were causing my tenured generation heap to grow was because SeeFusion uses a very low priority for writing these errors to the log. I believe all this log write request were getting queued up in the tenured generation and then would get written to the log when the load reduced or overall memory usage would grow too high. This theory seems to correlate with the time stamps on my coldfusion-out.XXX.log files, as I'd see a bunch of logs all written/updated at the same time.
So, if you happen to be running a really old version of SeeFusion like I was, contact the guys at Webapper about upgrading. This issue has been fixed in SeeFusion v4.0.6 and the latest version is fully tested with CF8. They were a lot of help yesterday in answering my various questions and they worked with my to quickly upgrade my version of SeeFusion to v4.0.6.
I'd also like to think Robi Sen for all his help in helping me track down this issue. He provided me lots of good guidance that lead me to find the root cause.
Comments for this entry have been disabled.