I'm on LLBLGen pro 3.5, and would like to log the linq query. With Microsoft linq to Sql, one simply calls DataContext.Log [ http://msdn.microsoft.com/en-us/library/system.data.linq.datacontext.log.aspx ]

I was able to log non-Linq queries by overriding CommonDaoBase -DaoBaseExecuteActionQuery(...) -ExecuteMultiRowDataTableRetrievalQuery -ExecuteMultiRowRetrievalQuery -ExecuteScalarQuery -ExecuteSingleRowRetrievalQuery as described here http://rapiddevbookcode.codeplex.com/SourceControl/changeset/view/67103#1106733

However, unfortunately, these overrides do not intercept Linq calls.

Notes: The trace shows these method calls 1) Method Exit: CreateSelectDQ Method Exit: CreatePagingSelectDQ: no paging.

2) LinqSupportClasses.LLBLGenProProvider.ExecuteValueListProjection ORMSupportClasses.DaoBase. GetAsProjection

Thanks, Ron

You could simply call: query.Expression.ToString(). Example:

var q = from o in metaData.Order
        where o.Customer.CompanyName.StartsWith("A")
        orderby o.EmployeeId
        select o;

Console.WriteLine("query: {0}", q.Expression.ToString());

// above code will output:
query: value(SD.LLBLGen.Pro.LinqSupportClasses.DataSource2`1[NW.LLBL.MSSQL.Adapter.v35.EntityClasses.OrderEntity]).Where(o => o.Customer.CompanyName.StartsWith("A")).OrderBy(o => o.EmployeeId)

You also could trace the expression and then write a custom trace listener to grab it.

<system.diagnostics>
  <switches>
    <add name="LinqExpressionHandler" value="3" />
  </switches>
</system.diagnostics>

Daelmo,

First thanks for your post, but I'm looking to log the actual sql query (not the Linq expression). Also, the goal, as in the posted URL [ http://rapiddevbookcode.codeplex.com/SourceControl/changeset/view/67103#1106733 ] was to intercept the query, and do my own custom logging (not the diagnostics switches that log to the Output window).

The key question is: what method needs to be overridden to intercept or see the actual Sql query, and then say, present the query in a message box?

Thanks, Ron

You can derive from the DatabaseDQE file used, and override the CreateSelectDQ method, and similar methods. There you should do your own logging and call the base method.

(edit)I didn't see you already tried tracing. You can customize the logging from the info obtained from the trace output though. It's just text and the queries are always logged the same way so you can easily intercept when a log is a query or when it's another element.

------- original message: You can do so, by adding a trace listener to your application. Trace listeners are part of .NET and how to set them up (e.g. a text listener to a file, or a stream) is described in the MSDN documentation (search for trace listeners, there are several built into .net, and you can also write them yourself)

Then you can enable tracing for the DQE to get the generated SQL queries, or other tracers to get additional information. please see: http://www.llblgen.com/documentation/3.5/LLBLGen%20Pro%20RTF/hh_goto.htm#Using%20the%20generated%20code/gencode_troubleshootingdebugging.htm#conventions

If you want to get the exact query as executed at that moment, you perhaps need a DQE override, like described above. Though for general purpose logging, the tracers can be sufficient. They emit everything as text so if you need the actual object, you need a DQE override.

Our profiler (orm profiler, http://www.ormprofiler.com) also shows the queries executed, but it's an additional tool. You might first want to try the tracers

Frans,

I'm not using TranceListeners; I'm using a custom logging class based on the EnterpriseLibrary5.

Can you please provide me an example of a 'DQE override' class+method?

Note: I'm assuming this one override should 'catch' all linq called queries as I've done w/CommonDaoBase.ExecuteActionQuery() and other methods.

Thanks, Ron

Linq calls are executed either through ExecuteMultiRowRetrievalQuery for entity fetches or GetAsProjection for fetching a normal projection. The latter isn't virtual.

You can do two things: 1) create a custom trace listener to listen to the DQE tracers or the ORMPersistenceExecution tracer. This is very easy and generic: you'll get ALL info you need at all time. Creating a tracer is easy, see: http://msdn.microsoft.com/en-us/library/sk36c28t.aspx

The purpose of this trace listener is to call the Enterprise library logging application block's LogWriter to write into the trace sources of the application block. That's all you have to do.

2) create a derived class of the SqlServer Dynamic Query Engine class and override CreateSelectDQ to intercept the query creation. Then, you use an altered CommonDaoBase class where you create an instance of your DynamicQueryEngine class in the CTor instead of the one that's there now.

I'd seriously recommend option 1, not only because it's way easier, it's also less intrusive: you can attach/detach the logging at any time without changing any code.

Frans,

1. Thanks for your advice - I went w/option 1/TraceListener as you recommended.
2. I noticed receiving many messages beyond the the query text, such as Entering and Exiting method this and that. The problem was the query is only 'visible' on Verbose/4 for ORMPersistenceExecution switch. I was hoping it would be on Info/3 and then, the code wouldn't need to keep on checking if the message text is the query.

My questions are: a. Is there a way to reduce the 'message traffic' but still get the query? -- e.g. override a method somewhere? in dao/dqe/base etc.? b. Is performance impact negligible?

Thanks, Ron

RonENT wrote:

Frans,

1. Thanks for your advice - I went w/option 1/TraceListener as you recommended.
2. I noticed receiving many messages beyond the the query text, such as Entering and Exiting method this and that. The problem was the query is only 'visible' on Verbose/4 for ORMPersistenceExecution switch. I was hoping it would be on Info/3 and then, the code wouldn't need to keep on checking if the message text is the query.

True. In your trace listener, check for '\tQuery:' (so \t==tab). After that the sql query is stated. The parameter values are listed below that, using '\tParameter:' lines. You can skip all other lines, so only log those. \tQuery is the line following 'Executed Sql Query'. So you can also check for that, and start logging there till you don't see a Query: or Parameter: line.

You can also intercept tracing of the DQE itself btw. (so this is another trace listener, see 'troubleshooting and debugging' in the manual) This is less verbose (you only see the queries) but it traces all SQL generated. This means it might log a sql fragment twice: if it's a subquery inside another query, the subquery is logged twice: once when it's generated and once inside the main query it's part of. Hence my suggestion to log it using the persistence execution tracer

My questions are: a. Is there a way to reduce the 'message traffic' but still get the query? -- e.g. override a method somewhere? in dao/dqe/base etc.? b. Is performance impact negligible?

Thanks, Ron

a: see above b: tracing costs some performance. If performance is critical, you should look into option 2 and as soon as the command is executed, off-load it to a separate thread for the logging.

Logging takes performance as well, so I'm not sure in what way you're going to use the logging. If it's for logging what happens no matter what, you might also want to look into Auditing, which can be implemented in an Auditor object and which allows you to log data access actions (but not fetches). If it's for troubleshooting during problematic situations, it might be specific tools are a better fit.

I'm not seeing any difference using DQE. It does not work as you described. <add name="SqlServerDQE" value="4" />

Using "3" - only Method enter/exit are shown (no query). Using "4"/verbose - get methods + query.

The manual-Troubleshooting and debugging says the same as what I get.

Seems like there is no way to reduce 'message traffic' using SqlServerDQE - you have to gov 4/Verbose to get the query.

Unless it's another 'undocumented' switch??

Thanks. Ron

RonENT wrote:

I'm not seeing any difference using DQE. It does not work as you described. <add name="SqlServerDQE" value="4" />

Using "3" - only Method enter/exit are shown (no query). Using "4"/verbose - get methods + query.

I never said that with the DQE tracing you'd 'just get the query', I mentioned it because it would only give you query info and not e.g. information about setting this or that or which entity was fetched/saved. So it's method enter/exits + only query info.

My point is that the trace listeners available will give you the query and perhaps some other fluff that's easy to filter out. Method enter/exits are always traced to give context to the info, as otherwise it's hard to place what happened when. But for your tracer/logger this isn't that important, so if a method enter/exit arrives in your trace listener, just ignore it.

As the query strings are always traced with the same prefix, it's not hard to pick them out of the stream of trace messages arriving at your trace listener. (A string.StartsWith() is enough).

It seems like we're not quite on the same page here. I'm long done implementing the TraceListener/filter - I've implemented it since your 1st suggestion to use it. My question was not about how to filter/find the query string, since I'm long done.

The question was performance driven - is there a way to reduce 'message traffic' - i.e., can I override a method not to send those Method Entry/Exit in the first place?

If not, this is an "enhancement request" to trace only the query and nothing else - this is the most interesting/useful part (for some of us) I'm focused on.

Note: Theoretically, the query could have been made available at Info level (3), and the method Entry/Exit in verbose (4) as it is really verbose [probably 50 to 1 ratio of method traces vs. query].

Thanks, Ron

That would be a feature request, indeed. I'll report it.

RonENT wrote:

It seems like we're not quite on the same page here I'm long done implementing the TraceListener/filter - I've implemented it since your 1st suggestion to use it. My question was not about how to filter/find the query string, since I'm long done.

The question was performance driven - is there a way to reduce 'message traffic' - i.e., can I override a method not to send those Method Entry/Exit in the first place?

If not, this is an "enhancement request" to trace only the query and nothing else - this is the most interesting/useful part (for some of us) I'm focused on.

Note: Theoretically, the query could have been made available at Info level (3), and the method Entry/Exit in verbose (4) as it is really verbose [probably 50 to 1 ratio of method traces vs. query].

Thanks, Ron

For what trace listener do you want this, the DQE or the persistence execution?

Also, you haven't answered my question why you'd want this. If it's informal information during development, it requires a different approach than when you want to provide the low-level SQL to the user of your application. If performance is an issue, I really wonder why you'd want to log the queries at all at any time, as it will be a tremendous amount of information. I.o.w.: don't you simply want to get insight in what happened at some specific times, not always? And also only when something is wrong?

I'd want this for ORMPersistenceExecution. The query trace would be on at all times on Production (not testing / development).

The reason for having it on always is three-fold: 1. Many times the problems are intermittent so it's not clear when to turn it on (e.g., problem happens once in a couple weeks). 2. To have immediate support/log info. at any time for quick response to customer - i.e,. proactiveness. As opposed to customer calls... give me some time.. I'll turn the log on... and so on. The bottom line is that when the customer calls urgently for help on a 24x7 site, having the query logged can make a big difference. 3. To have 'monitoring' info when desired.

Note: The log is a rolling file, which can be aged - e.g., limit log window to 3 days , 1 GB, etc..

Ron

Ok. Sounds reasonable.

The logging of the query is now IMHO not efficient enough to be enabled as an always on system as it's executed on the calling thread and serializes the parameter values into the output string.

Do you need the parameter values at level 3 as well? Because emitting the query to the output without the parameter values would be more efficient.

I would prefer having the parameters but if I could choose to have them w/o method entry/exit that would help.

e.g., 3= query w/o params 4=query w/params

if there were a 5 value as an ExtraVerbose, then 5=method entry/exit

Thank you. Ron

RonENT wrote:

I would prefer having the parameters but if I could choose to have them w/o method entry/exit that would help. e.g., 3= query w/o params 4=query w/params if there were a 5 value as an ExtraVerbose, then 5=method entry/exit

The levels are unfortunately provided by .NET, not us

I'll see what I can do for you with respect to v3.5 and level 3 of ormpersistence tracing and query logging. I'll get back to you on that.

all method enter/exists are at level 3, so bumping these to level 4 and adding the query to level 3 is a significant change.

We'll add a new trace listener for executed queries alone with at level 3 just the query and at level 4 the query + parameters. If one has enabled both, it's redundant, but as these are for diagnostics I don't see why one would enable both.

I'll have the updated runtime tomorrow (friday)

Perfect!

I'll be using the new switch only - e.g., <add name="Queries..." value="3" /> <!-- to log queries only -->

Thanks. Ron

See attached dll.

Tracer name: ORMQueryExecution Info level emits:

Executed Sql Query: 
    Query: INSERT INTO [LLBLGenProUnitTest].[dbo].[AuditInfo] ([ActionData], [ActionDateTime], [ActionType], [AffectedEntityName]) VALUES (@p1, @p2, @p3, @p4) ;SELECT @p5=SCOPE_IDENTITY()

Verbose level emits:

Executed Sql Query: 
    Query: INSERT INTO [LLBLGenProUnitTest].[dbo].[AuditInfo] ([ActionData], [ActionDateTime], [ActionType], [AffectedEntityName]) VALUES (@p1, @p2, @p3, @p4) ;SELECT @p5=SCOPE_IDENTITY()
    Parameter: @p1 : AnsiString. Length: 2000. Precision: 0. Scale: 0. Direction: Input. Value: "RelatedEntityName: AddressEntity. MappedFieldName: BillingAddress".
    Parameter: @p2 : DateTime. Length: 0. Precision: 0. Scale: 0. Direction: Input. Value: 26-10-2012 12:28:59.
    Parameter: @p3 : Int32. Length: 0. Precision: 10. Scale: 0. Direction: Input. Value: 5.
    Parameter: @p4 : AnsiString. Length: 50. Precision: 0. Scale: 0. Direction: Input. Value: "CustomerEntity".
    Parameter: @p5 : Int32. Length: 0. Precision: 10. Scale: 0. Direction: Output. Value: 151106.

usage:

    <system.diagnostics>
        <switches>
            <add name="ORMQueryExecution" value="4"/>
        </switches>
    </system.diagnostics>

where value can be 0 (off) 3 (info) or 4 (verbose)

This switch is an official switch and will be part of the runtime from now on, so you can rely on it being there. Start build: v3.5 buildnr 10262012

Another change is that it now also logs sequence retrieval queries, which were omitted in other tracers. These queries are only used with sequence using databases like oracle, postgresql, db2 and firebird.

Let me know whether this works for you (I think it will )

Sounds very good.

Where and when would I look to download this build[buildnr 10262012]?

Is there Email notification for upgrades? or a regulard schedule I should check a url? (e.g, 1x/ month)

Note: I'm on 3.5 -June 27th, 2012. And not sure if there is a build past it? or I'm on the latest?

Ron

RonENT wrote:

Where and when would I look to download this build[buildnr 10262012]?

Generally any change is included in the next build.

RonENT wrote:

Is there Email notification for upgrades? or a regulard schedule I should check a url? (e.g, 1x/ month)

You can suscribe to the download updates rss: https://www.llblgen.com/Pages/RssDownloads.aspx

RonENT wrote:

Note: I'm on 3.5 -June 27th, 2012. And not sure if there is a build past it? or I'm on the latest?

The latest build is "September 17th, 2012". If you are not sure, just download the latest from the customer area.

I attached the dll my previous post above, which is a release build so you can use that one from now on till a next build is released on the site. It supports the trace listener.

Frans - thanks, I got the attached dll - works great - trace listener 'sees' only queries (very clean!)