Posts Tagged ‘Logging’

SP 2010: Developing for performance Part 4 – Logging

January 17th, 2011 by Tobias Zimmergren

Author: Tobias Zimmergren
http://www.zimmergren.net | http://www.tozit.com | @zimmergren

Introduction

SharePoint 2010 developing for performance article series:
In this series of articles I will briefly introduce you to some key concepts when it comes to developing for performance in our SharePoint 2010 applications.

Related articles in this article series

Part 1 – SP 2010: Developing for performance Part 1 – Developer Dashboard
Part 2 – SP 2010: Developing for performance Part 2 – SPMonitoredScope
Part 3 – SP 2010: Developing for performance Part 3 – Caching in SharePoint 2010
Part 4 – SP 2010: Developing for performance Part 4 – Logging
Part 5 – SP 2010: Developing for performance Part 5 – Disposal patterns and tools
Part 6 – SP 2010: Developing for performance Part 6 – CSS Sprites
Part 7 – SP 2010: Developing for performance Part 7 – Crunching those scripts
Part 8 – SP 2010: Developing for performance Part 8 – Control that ViewState

Part 4 (this article):
In SharePoint 2010 (well, 2007 too for that matter) you need to think about proper logging in your applications to ensure that any problems, issues or other events are lifted to the ULS Logs (Unified Logging System) – that way the administrators can easily view the logs and track down problems with your applications. In this article I will talk a bit about how you can utilize the logging capabilities in SharePoint 2010.

ULS Logs

The ULS Logs are the main place for SharePoint to output it’s diagnostics information. We will take a quick look at how we can read the logs and obviously how we can write custom logging messages to the logs.

Reading the ULS Logs in SharePoint 2010

In order to read the ULS Logs you’ll need access to the SharePointRoot (14LOGS) folder. But to make the life even easier for us Microsoft released a tool called the ULS Viewer which you can download here: http://code.msdn.microsoft.com/ULSViewer

With this tool you can quite easily read through the logs in SharePoint 2010 without any issues.

There’s plenty of resources on the web about how to use the ULS Viewer, so go take a look at any one of them for some usage-instructions.

Download (docx): ULS Viewer documentation

Writing to the ULS Logs from you SharePoint 2010 application

The other side of the logs are of course writing to the logs. This is not a very hard task to do in SharePoint 2010, and I’ll outline the basic steps to do so here.

Normally I create a new class or at least a method to take care of the logging, and it can look like this:

public static void WriteTrace(Exception ex)
{
    SPDiagnosticsService diagSvc = SPDiagnosticsService.Local;
    diagSvc.WriteTrace(0,
        new SPDiagnosticsCategory("TOZIT Exception",
            TraceSeverity.Monitorable,
            EventSeverity.Error),
        TraceSeverity.Monitorable,
        "An exception occurred: {0}",
        new object[] {ex});
}

You can use the aforementioned code by calling the method like so:

try
{
    throw new Exception("Oh no, application malfunctioned! UnAwesomeness!!!");
}
catch(Exception ex)
{
    WriteEvent(ex);
}

It’s not very hard at all – once you’ve done that, you’re all set to kick off your custom applications and just call your custom logging method. Obviously you should create a proper logging class to take care of all your logging in your applications.

Results

Using the ULS Viewer you can easily track down the error messages by filtering on your category (in my case it’s TOZIT Exception)

image

image

Event Logs

Even though the ULS Logs takes care of most of the diagnostics logging today, it might be reasonable to output information into the Event Logs sometime.

Writing to the Event Logs from you SharePoint 2010 application

Just as when you’re doing ULS Logging, you can do logging to the Event Logs. It’s just as simple, but you replace the method "WriteTrace" with "WriteEvent" like this:

public static void WriteEvent(Exception ex)
{
    SPDiagnosticsService diagSvc = SPDiagnosticsService.Local;
    diagSvc.WriteEvent(0,
        new SPDiagnosticsCategory("TOZIT Exception",
            TraceSeverity.Monitorable,
            EventSeverity.Warning),
        EventSeverity.Error,
        "Exception occured {0}", new object[] {ex});
}

Results

You can view the logs in the Event Logs on your SharePoint server as you would read any other logs.

image

Can I do more?

There’s plenty of cool things to do with the logging mechanism in SharePoint 2010, so you should definitively get your hands dirty playing around with it.

If you for example want to tag the log entries with your company name, clients name or project name – you can easily change that behavior as well. Take a look at my friend Waldek’s post about it here: http://blog.mastykarz.nl/logging-uls-sharepoint-2010/

Related resources

Summary

As a part of the article series focusing on some general guidelines for performance in your applications, logging is a major player. If you master your logs in terms of monitoring and custom application logging you will quickly come to realize how valuable it is.

This is intended as a starting point for you to get familiar with the logging-capabilities in SharePoint 2010.

SP 2010: Developing for performance Part 2 – SPMonitoredScope

December 21st, 2010 by Tobias Zimmergren

Author: Tobias Zimmergren
http://www.zimmergren.net | http://www.tozit.com | @zimmergren

Introduction

SharePoint 2010 developing for performance article series:
In this series of articles I will briefly introduce you to some key concepts when it comes to developing for performance in our SharePoint 2010 applications.

Related articles in this article series

Part 1 – SP 2010: Developing for performance Part 1 – Developer Dashboard
Part 2 – SP 2010: Developing for performance Part 2 – SPMonitoredScope
Part 3 – SP 2010: Developing for performance Part 3 – Caching in SharePoint 2010
Part 4 – SP 2010: Developing for performance Part 4 – Logging
Part 5 – SP 2010: Developing for performance Part 5 – Disposal patterns and tools
Part 6 – SP 2010: Developing for performance Part 6 – CSS Sprites
Part 7 – SP 2010: Developing for performance Part 7 – Crunching those scripts
Part 8 – SP 2010: Developing for performance Part 8 – Control that ViewState

Part 2 (this article):
In this article I will talk briefly about what SPMonitoredScopes are and how you can utilize them in combination with your developer dashboard to get some stats and performance information about your custom applications.

SPMonitoredScope to track performance in your applications

The monitored scope (SPMonitoredScope) is a class you can use to monitor performance and resource usage in your applications by using it in a simple code block.

The pros about using the monitored scopes are of course that you can easily track down and find bottlenecks as well as do some initial performance monitoring while doing your development.

Using SPMonitoredScope

In order to use the SPMonitoredScope you’ll need to add a using statement for Microsoft.SharePoint.Utilities and then wrap your code in a statement like this:

using (new SPMonitoredScope("CallMethod1 Monitored Scope"))
{
    Controls.Add(new Literal {Text = "Awesomeness<br/>"});
}

You don’t need to add any more code than this in order for it to be hooked up.

See the results

So what now, what if I’ve added some monitored scopes to some of my classes – where can I see the results?

Answer: Open up your developer dashboard on the page where your code is executing and pow, you’ll see it right there:

Note: I’ve added three monitored scopes in my code, as seen below named CallMethod1,2,3
image

You can see that the CallMethod3 is the one dragging this page down in my particular case. Easy enough to keep track of the request time for your pages!

You can even nest your scopes

If you’ve got nested method calls and a bit more code (you’re likely to have that), you can of course nest your monitored scopes. There’s nothing to it really, you can instantiate new monitored scopes inside of a monitored scope:

using (new SPMonitoredScope("My Monitored Scope"))
{
    Controls.Add(new Literal { Text = "When the awesomeness is flying… " });
               
    using (new SPMonitoredScope("My Sub-Monitored Scope"))
    {
        Controls.Add(new Literal { Text = "there’s no stopping it! " });

        using (new SPMonitoredScope("My Sub-Sub-Monitored Scope"))
        {
            Controls.Add(new Literal { Text = "<br/>I’m three levels deep!" });
        }

        using (new SPMonitoredScope("Another deep scope"))
        {
            Controls.Add(new Literal { Text = "Rock and rumble, rock and rumble" });
        }
    }
}

Results: Nested scopes (My Monitored Scope)!
image

Limitations

The SPMonitoredScope is NOT available for Sandboxed solutions unfortunately, so this neat trick will not work if you’re planning on deploying to the sandbox.

Summary

This was a short introduction to the SPMonitoredScope class that you can utilize in SharePoint 2010 when doing custom development. The pros with using these monitored scopes is that you can easily track performance of your custom applications using the Developer Dashboard without even hooking up any debugger or external performance monitor to your servers – this is all done and visualized in the web browser upon displaying the Developer Dashboard.

This is a very easy trick to keep an eye out for performance bottlenecks in your applications for SP 2010.

Enjoy!

Author: Tobias Zimmergren
http://www.zimmergren.net | http://www.tozit.com | @zimmergren

Introduction

SharePoint 2010 developing for performance article series:
In this series of articles I will briefly introduce you to some key concepts when it comes to developing for performance in our SharePoint 2010 applications.

Related articles in this article series

Part 1 – SP 2010: Developing for performance Part 1 – Developer Dashboard
Part 2 – SP 2010: Developing for performance Part 2 – SPMonitoredScope
Part 3 – SP 2010: Developing for performance Part 3 – Caching in SharePoint 2010
Part 4 – SP 2010: Developing for performance Part 4 – Logging
Part 5 – SP 2010: Developing for performance Part 5 – Disposal patterns and tools
Part 6 – SP 2010: Developing for performance Part 6 – CSS Sprites
Part 7 – SP 2010: Developing for performance Part 7 – Crunching those scripts
Part 8 – SP 2010: Developing for performance Part 8 – Control that ViewState

Part 1 (This article):
This is Part 1 of 5 where I will introduce you to the developer dashboard in SharePoint 2010. The reason for the developer dashboard being a key concept in your SharePoint development tasks is the quick and effective manner of which you can start looking for bottlenecks and problems in your installation without launching any additional tools.

SharePoint 2010 Developer Dashboard

The developer dashboard is a perfect tool for anyone who wants a quick way to access information about what goes on while rendering a page in SharePoint. It contains information about Web Parts, events, DB calls and a whole lot of nifty information.

Activating the Developer Dashboard

Developer Dashboard is a utility that is available in all SharePoint 2010 versions, and can be enabled in a few different ways:

  • PowerShell
  • STSADM.exe
  • SharePoint Object Model (API’s)

Using these different approaches is very simple; All you will need to do is use one of the aforementioned methods to activate the dashboards, as described here:

Activate the Developer Dashboard using PowerShell:

$devdash =
Microsoft.SharePoint.Administration.SPWebService]::ContentService.DeveloperDashboardSettings;
$devdash.DisplayLevel = ‘OnDemand’;
$devdash.TraceEnabled = $true;
$devdash.Update()


Activate the Developer Dashboard using STSADM.EXE

STSADM.EXE -o setproperty -pn developer-dashboard -pv ondemand

Activate the Developer Dashboard using the SharePoint Object Model

using Microsoft.SharePoint.Administration;

SPWebService svc = SPContext.Current.Site.WebApplication.WebService;
svc.DeveloperDashboardSettings.DisplayLevel =
    SPDeveloperDashboardLevel.Off;
svc.DeveloperDashboardSettings.Update();

Note that in the preceding samples I’ve used a property called "OnDemand". This can be set to the following values:

  • Off (Disables the Developer Dashboard)
  • On (Enables the Developer Dashboard)
  • OnDemand (Enables the Developer Dashboard upon request by clicking the icon in the upper right corner)

If the Developer Dashboard is set to OnDemand, this button appears in the top right corner just next to your login name:
image

As a side note, you can also enable Tracing for your developer dashboard to enable your dashboard to display the asp.net page trace. I will cover this a bit further down.

Reading the Developer Dashboard information

When you click the small icon in the top right corner, the Developer Dashboard will be opened and displayed at the bottom of your page.

Developer Dashboard example:
image

You can see that it has a Green border right now. That generally means it’s loading quick enough not to be a real problem. It can also render Yellow, which indicates that there’s a slight delay and then it could render a Red border which would mean you definitely need to look into it immediately!

So, what information can you read out of this?

Page Request to the left-hand side

You can read out the Page Request, and see what loads and how long it takes to load. This is perfect to use to track down heavy-loading apps or finding out what’s taking so long to render the page;
image

Web Server, Events, DB Queries, Service Calls, SPRequests, Web Part Events on the right-hand side

image

Dig deeper into the SQL DB queries by clicking on the link

If you’d like to get some more in-depth information about what query was shot away to the DB, click the hyperlink corresponding the query you want to find out about and you’ll see something like this;

image

Displaying ASP.NET Trace information

One thing that I absolutely love about this tool is the ability for the tool to enable Tracing (this should be enabled when you enable the Developer Dashboard using the SP Object Model or PowerShell by setting the following flag:

DeveloperDashboardSettings.TraceEnabled = true;

If you’ve done this, and you’ve got the Developer Dashboard enabled – you should see the following link in the bottom left area of the developer dashboard:
image

If you click it, you’ll see the full ASP.NET Page Trace like this (awesome, very very awesome):
image

The beauty about this is you don’t have to go and edit the web.config and enable tracing there – you just click this little button and it’s all done. I love it.

Developer Dashboard Visualizer – Extend your developer dashboard with diagrams

One of my friends Jaap Vossers wrote up a cool functionality to use in conjunction with the Developer Dashboard – Developer Dashboard Visualizer – which is a cool utility if you want to visualize what the rendering process looks like on your page.

If you’ve downloaded this awesome solution, you’ll see a new Site Collection feature that you’ll need to enable:
image

Once that’s done, next time you’ll visit the Developer Dashboard awesomeness it’ll look something like this:
image

Developer Dashboard activation as a Feature

My good friend Wictor Wilén wrote a quick and cool feature to ease the activation of the Developer Dashboard settings (find it here) which allows you to more easily change the settings of the developer dashboard without doing it by typing any scripts or code.

Once you’ve downloaded and installed the solution, you’ll find a new Farm feature that should be activated, which provides some functionality to Central Administration for administering the Dev Dashboard:
image

If you’ve deployed and got this feature activated, head on over to General Application Settings and you’ll see that you’ve got a new header called "Development Settings" containing a link to "Developer Dashboard Settings".

Click it and you’ll see this very awesome page that enables you to configure the Developer Dashboard without actually writing any code!

image

Summary

In this article you’ve read about the Developer Dashboard and how to enable it, and a few extra tips that you can download and install to make your experience with the Developer Dashboard even cooler.

This was part 1 in an article series talking about a few concepts we’ll need to understand in order to properly plan and design for performance in our SharePoint 2010 applications.

Stay tunes for parts 2-5.

Enjoy!

Author: Tobias Zimmergren
http://www.zimmergren.net | http://www.tozit.com | @zimmergren

Introduction

In SharePoint 2010, you’ve got some new capabilities for error reporting and logs. One of the most noted features for me as a developer is that whenever you bump into an error message – you’ll be presented with a correlation ID token.

In this article I will try to explain how you can fetch that token from SharePoint, and also provide a small snippet of code to be able to build your own “Log Searcher Web Part” for your administrators.

Correlation ID, what’s that?

In SharePoint 2010, you get a Correlation ID (which is a GUID) attached to your logs/error messages when something happens. This ID can then be used to lookup that specific error from the logs.

This Correlation ID is used per request-session in SharePoint 2010, and if you are in the process of requesting some information from SharePoint and bump into some problems along the way – your Correlation ID will be the best starting point for searching for what went wrong along that request!

You might get an error message like this in SharePoint 2010 (don’t worry, if you haven’t seen one like this one yet – just hang in there, sooner or later you will.. Winking smile)

image

Search for the log messages based on the Correlation ID token

So if you’ve gotten such an error message and want to find out more information about the actual error and don’t have the time to go around poking in the logs and searching – there’s a few methods you can do this rather easily, as described below.

Using PowerShell to lookup a log message based on Correlation ID token

One of the quick-n-awesome ways to do this is to simply hook up a PowerShell console (SharePoint 2010 Management Shell) and then just write the following command (replace the <GUID> with the Correlation Id):

get-splogevent | ?{$_Correlation -eq "<GUID>" }

This will give you the details about your specific error like this in the console:

image

You might want to be more precise and get more specific details out of your query, then you can try something like this:

get-splogevent | ?{$_.Correlation -eq "<GUID>"} | select Area, Category, Level, EventID, Message | Format-List

This will give you the details about your specific error like this with some juicy details:

image

Finally if you would want these messages to be put into a text or log file instead, you could just add the classic “> C:Awesome.log” after the command like this:

get-splogevent | ?{$_.Correlation -eq "<GUID>"} | select Area, Category, Level, EventID, Message | Format-List > C:Awesome.log

image

On MSDN they have an overvoew of using SP-GetLogEvent which I would recommend!

Using SQL queries to find log message based on Correlation ID token

You can utilize the SQL logs database to fetch the specific error message based on Correlation id as well. In your logging DB (usually called WSS_Logging, but can be called something else if you’ve changed it) there is a view called ULSTraceLog which you can query with a simple SQL query and fetch the results.

I’ve created a query to fetch the items from the logging database like this:

 select 	[RowCreatedTime],  [ProcessName],  [Area],  
 		[Category],  EventID,  [Message] 
 from  [WSS_UsageApplication].[dbo].[ULSTraceLog] 
 where  CorrelationId=< pre>'B4BBAC41-27C7-4B3A-AE33-4192B6C1E2C5'

This will render your results in the SQL Query window like this:

image

This can of course be implemented in a Web Part for your convenience as well (I’ve created a bunch of diag. and logging web parts that I’ve got deployed to Central Admin) that could look like this (this way you don’t need physical access to the ULS logs all the time, but can do a quick lookup from the web part):

image

Get the current Correlation ID by using code

I got this piece of code from my good friend Wictor’s blog post. Thanks Wictor – this made my Logging-project more satisfying!

With the following code you can fetch the current Correlation Id of a request.

Create a method (in my case called GetCurrentCorrelationToken()) to wrap up the functionality of returning the current token like this:

 public  class  CorrelationId 
 {
     [DllImport ("advapi32.dll")]
     public  static  extern  uint  EventActivityIdControl(uint  controlCode,ref  Guid  activityId);
     public  const  uint  EVENT_ACTIVITY_CTRL_GET_ID = 1;

     public  static  Guid  GetCurrentCorrelationToken()
     {
         Guid  g = Guid .Empty;
         EventActivityIdControl(EVENT_ACTIVITY_CTRL_GET_ID, ref  g);
         return  g;
     }
 }

Then from wherever in your code you can simply call it by using this approach:

 protected  void  Button1_Click(object  sender, EventArgs  e)
 {
     Label1.Text = CorrelationId .GetCurrentCorrelationToken().ToString();
 }

(Normally you might want this in a try/catch statement or something like that)

image

Summary

This article should give you (administrator and developer) an insight in how you easily can track the specific errors your users encounter in their/your application(s). If a user gets an error message in SharePoint 2010, they’ll also see the Correlation ID.

If you can train your users to write down that Correlation ID along with a few simple steps on how the error might have been occurring, you’re going to have a much easier way to find the details about that specific error than ever before.

Enjoy!