I'm getting ridiculously fat log file, from these loading every few seconds since upgrading to Umbraco 7.3!
Looking back through the log history, these we'rent previously a feature of INFO in logging, I'm also concerned the application pool memory is rising to over 1GB. Which is a heck of a lot of RAM.
Any ideas why?
Martin
2015-10-14 16:02:54,928 [8] INFO umbraco.macro - Xslt node adding search start (documentTypeAlias,'news')
2015-10-14 16:02:54,928 [8] INFO umbraco.macro - Complete (took 0ms)
2015-10-14 16:02:54,928 [8] INFO umbraco.macro - Xslt node adding search start (rssDescription,'The latest news from LCP.')
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms)
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Xslt node adding search start (filterType,'')
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms)
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Xslt node adding search start (rssTitle,'Lane Clark & Peacock LLP - News')
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms)
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:Exslt.ExsltCommon, ExsltCommon
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms)
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:Exslt.ExsltDatesAndTimes, ExsltDatesAndTimes
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms)
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:Exslt.ExsltMath, ExsltMath
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms)
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:Exslt.ExsltRegularExpressions, ExsltRegularExpressions
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms)
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:Exslt.ExsltSets, ExsltSets
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms)
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:Exslt.ExsltStrings, ExsltStrings
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms)
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:Examine, XsltExtensions
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms)
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:lcp.antixss, AntiXSS
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms)
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:lcp.encrypt, Encryption
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms)
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:lcp.searchNew, SearchNewSchema
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms)
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:lcp.server, ServerRequestUtils
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms)
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:lcp.trans, Translation
2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms)
It is typical for the application pool to take up lots of memory (e.g., I picked a random site of mine, and it's 423MB). IIS is very conservative in its garbage collection. My guess is it avoids garbage collection as much as possible to improve performance.
Regarding the INFO items in your Umbraco log, perhaps that is the result of a configuration change applied by Umbraco 7.3? Maybe in the log4net.config file (I think you can configure the log level, which basically dictates what severity of logs entries to write to the file).
No the level has always been set to INFO by default, and prior to 7.3 we would get lots of useful "INFO" but not this. It's a whole chunk of entries every few seconds, which indicates them being loaded with every page request. It's not something I think should be logged due to what its doing to the log file.
Anyways i've set to WARN as the lowest level for now,
As for memory usage, a lot of work had been done recently to get memory usage down, we noticed a significant decrease, to around 400-500MB. But since moving to 7.3 its crept back up to 1-1.3GB.
umbraco.macro INFO adding every few seconds!
I'm getting ridiculously fat log file, from these loading every few seconds since upgrading to Umbraco 7.3!
Looking back through the log history, these we'rent previously a feature of INFO in logging, I'm also concerned the application pool memory is rising to over 1GB. Which is a heck of a lot of RAM.
Any ideas why? Martin
2015-10-14 16:02:54,928 [8] INFO umbraco.macro - Xslt node adding search start (documentTypeAlias,'news') 2015-10-14 16:02:54,928 [8] INFO umbraco.macro - Complete (took 0ms) 2015-10-14 16:02:54,928 [8] INFO umbraco.macro - Xslt node adding search start (rssDescription,'The latest news from LCP.') 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms) 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Xslt node adding search start (filterType,'') 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms) 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Xslt node adding search start (rssTitle,'Lane Clark & Peacock LLP - News') 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms) 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:Exslt.ExsltCommon, ExsltCommon 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms) 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:Exslt.ExsltDatesAndTimes, ExsltDatesAndTimes 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms) 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:Exslt.ExsltMath, ExsltMath 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms) 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:Exslt.ExsltRegularExpressions, ExsltRegularExpressions 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms) 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:Exslt.ExsltSets, ExsltSets 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms) 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:Exslt.ExsltStrings, ExsltStrings 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms) 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:Examine, XsltExtensions 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms) 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:lcp.antixss, AntiXSS 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms) 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:lcp.encrypt, Encryption 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms) 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:lcp.searchNew, SearchNewSchema 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms) 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:lcp.server, ServerRequestUtils 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms) 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Extension added: urn:lcp.trans, Translation 2015-10-14 16:02:54,944 [8] INFO umbraco.macro - Complete (took 0ms)
It is typical for the application pool to take up lots of memory (e.g., I picked a random site of mine, and it's 423MB). IIS is very conservative in its garbage collection. My guess is it avoids garbage collection as much as possible to improve performance.
Regarding the INFO items in your Umbraco log, perhaps that is the result of a configuration change applied by Umbraco 7.3? Maybe in the log4net.config file (I think you can configure the log level, which basically dictates what severity of logs entries to write to the file).
Hi Nicholas
No the level has always been set to INFO by default, and prior to 7.3 we would get lots of useful "INFO" but not this. It's a whole chunk of entries every few seconds, which indicates them being loaded with every page request. It's not something I think should be logged due to what its doing to the log file.
Anyways i've set to WARN as the lowest level for now,
As for memory usage, a lot of work had been done recently to get memory usage down, we noticed a significant decrease, to around 400-500MB. But since moving to 7.3 its crept back up to 1-1.3GB.
M.
is working on a reply...