6.1.1 - Stability problems and farLog error recording

[James Buckingham]

Hi group,

Over the past week we've been having a lot of stability issues. In fact since we went live with 6.1.1 mid-November our production server hasn't been the most reliable. We've also seen a large drop in page speed since go-live.

We're investigating what's going on at the moment and making a few changes to our server configuration but obviously with the biggest change being the upgrade that's were we're currently looking for answers.

I thought it best to post our findings so far and by all means if anyone has any recommendation on how to diagnosis and fix this it would be much appreciated.

-----

Looking at our JRun logs and the farLog table I'm seeing a large number of these types of errors appearing:-

12/07 22:06:59 Error [jrpp-499] - Error Executing Database Query. Column count doesn't match value count at row 1 [SQL:   INSERT INTO farLog ( CREATEDBY , LOCATION , LASTUPDATEDBY , TYPE , DATETIMELASTUPDATED , OBJECTID , NOTES , DATETIMECREATED , USERID , OBJECT , LOCKEDBY , LOCKED , EVENT   ) VALUES ( (param 1)  ,  (param 2)  ,  (param 3)   (param 4)  ,  (param 5)  ,  (param 6)  ,  (param 7)  ,  (param 8)  ,  (param 9)  ,  (param 10)  ,  (param 11)  ,  (param 12)  ,  (param 13)   ) ]

AND statement in the WHERE clause....

SELECT columns FROM dmImage WHERE AND objectid = '07CCA55F-1275-11DF-B173000D609CAA9E';

 

Duplicated LASTUPDATTEDBY in this one....

Column 'lastupdatedby' specified twice [SQL: INSERT INTO farLog ( CREATEDBY , LASTUPDATEDBY , LASTUPDATEDBY , TYPE , DATETIMELASTUPDATED , OBJECTID , NOTES , DATETIMECREATED , USERID , OBJECT , LOCKEDBY , LOCKED , EVENT )

---

I'm also seeing things like missing commas between column names.

At the last check earlier today the farLog table had accepted over 750 new error records, in a 24hr period, from user "anonymous" and is highlighting problems with calling the getData() method.

---

I've seen this kind of thing in the past and typically it comes down to a lack of "var"ing being applied in CFCs. I've run a copy of VarScoper against the Core today and I'm seeing a lot of results coming back. The ones that are jumping out at me though are the Gateways, in particular I'm getting 7 coming back from the BaseGateway referring to the variable bFirst.

That seems to be a flag used for determining how the SQL should be formatted and is used in a number of different functions. Given this is persisted and that variable is defaulting to global I'm pretty sure multiple requests are hitting the Gateway and causing these deformed queries.

My main concern here is that although this kind of thing is being logged by FarCry and handled by CF what are the ramifications of these objects constantly changing in state. The theory I currently have is that this problem could be going deeper and causing these server crashes we're now getting.

---

I'm going to need to fix these and probably review the others in more detail but as I say if anyone has any further advice it would be much appreciated :-).

Cheers,

James

[ad...@motorspor.com]

Hi James,

We were having slowness issue on FC 6.1 project. I have looked at the tables to see if any issues there and noticed 1.1 million records on refObjects table. We are also using Solr plugin and it is recording every single search. I have truncated farSolrLog table and deleted farSolrLog records from refObjects table as well.. The biggest improvements happened once I used repair refObjects table on webtop and site was very very fast afterwards.

Not sure if it is related to you but thought it might help you or others.

Tunç

--
You received this message cos you are subscribed to "farcry-dev" Google group.
To post, email: farcr...@googlegroups.com
To unsubscribe, email: farcry-dev+...@googlegroups.com
For more options: http://groups.google.com/group/farcry-dev
--------------------------------
Follow us on Twitter: http://twitter.com/farcry

[Blair McKenzie]

I've commited the var'd version to the p610 branch and trunk. If you still have the VarScoper report can you send me that. I thought we had been there and done that, but I guess not.

Blair

--

[James Buckingham]

Thanks guys,

Blair - That's me taken the update now, thanks a lot :-).

In terms of VarScoper I would email you the report but

a) I can't see an option in the new Google Groups to mail you :-)
&
b) I'm not getting a full report just now. It seems to just stop with a "stackoverflow error" when I hit the packages/farcry/genericAdmin.cfc so I'm only getting a handful back. I'll see if it improves as I work through these but in the meantime I've attached what I do have - hope it's of some help.

I think for now I'm going to have to fix the issues locally - I'll see how I get on and if people want me to report back then I'm happy to do so :-)

Cheers,
James

[James Buckingham]

Oops!! Attachment here

[James Buckingham]

A further update on this one from today's investigation.

I've applied some varring to the Core. To be honest VarScoper is giving me back a lot so without working out what's persisted and what's not it was easier to just focus on the main ones I've mentioned already.

We've not applied these yet but we have switch on CF Server Monitoring and that's brought up some interesting results.

It seems that the database (mySQL) is struggling to process some of the queries we're firing through to it. The biggest culprit being the News Listing Rules that are filtered by Category. Currently this type of query (see below) is taking around a 1mins to 2mins to process.

This generated through the FAPI getContentObject() method....

select objectid, 'dmNews' as typename
from dmNews
where1=1
AND status in ('approved')
AND
(
publishDate is null
OR publishDate = '2050-01-01 00:00:00'
OR publishDate > '2111-12-08 15:51:06'
OR publishDate <= '2011-12-08 15:51:06'
)
AND
(
expiryDate is null
OR expiryDate = '2050-01-01 00:00:00'
OR expiryDate > '2111-12-08 15:51:06'
OR expiryDate >= '2011-12-08 15:51:06'
)
AND
objectid in (
selectobjectid
fromrefCategories
wherecategoryid in ('xxxxxxxx,xxxxxxx')
group byobjectid
havingcount(objectid)=2
)
ORDER BY publishdate DESC;

----

We've tried switching on some indexing but that doesn't seem to have made any difference so a bit more delving into this we've found out the use of IN within mySQL is a real performance hit. A good article on it here:-

http://www.artfulsoftware.com/infotree/queries.php#568

The recommendation seems to be that the queries within getContentObjects, for mySQL anyway, should be formatted like so:-

objectid in (

select objectid from (

      select            objectid

      from        #application.dbowner#refCategories

      where       categoryid in (<cfqueryparam cfsqltype="#f.sqltype#" list="true" value="#f.value#" />)

      group by    objectid

      having            count(objectid)=<cfqueryparam cfsqltype="cf_sql_integer" value="#listlen(f.value)#" />

      ) as tmp

)

I'm still to test this in the project but we're certaintly seeing an improvement when we run this SQL directly through the database.

Anyway update over, hope it's of some help

Cheers,
James