SQL Server Error Logs??

Couple of days ago, I had conversation with a Jr.DBA regarding SQL Server Error Logs! She was confused with “Error Logs” under SQL Server Agent Node and “SQL Server Logs” under Management Node. In Fact, she was assuming that both are same which is not the case!!!

Also, I heard many times from many confused DBA’s that SQL Server Error logs can’t be accessed when the SQL Services are Offline, which is absolute Bogus!! SQL Server Error log is nothing but a plain Text file located in our “LOG” folder by default which can be opened using Notepad when you are not able to connect to SQL and see via SSMS.

In this blog post, let me make it clear what/Where are SQL Server Logs and what/Where are SQL Agent logs are. Please see below Screenshot.

As you can see we’ve “SQL Server Logs” – Under Management Node and “Error Logs”- Under SQL Server Agent.

Note: All these Error Logs(SQL Server Logs and SQL Agent Logs and any Dumps being created) will be located in “C:\Program Files\Microsoft SQL Server\MSSQL10_50.PROD\MSSQL\Log” location. – In my case, I’ve SQL Server 2008R2 and a named Instance ‘PROD’, hence folder “MSSQL10_50.PROD”. “LOG” folder is not for storing your Transaction Logs!!!

If you are confused even now, You can use T-SQL to read your Error Log.

How to read SQL Server Error Log from T-SQL??

Method 1: EXEC XP_READERRORLOG

Method 2: EXEC SP_READERRORLOG – This is UnDocumented way! But this gives lot more flexibility to select the number and filter the contents etc…For example I want to read the contents from my 5th Error Log which has the word “Master”.  For this, all i want to enter in my Query Pane is Exec Sp_ReadErrorlog  5, 1, ‘master‘. As you can see below I got only 4 records returned where ever word “master” is present.

Hope this helps…!

Advertisements

Few Useful(often Ignored) DBCC Commands…

Thought of compiling all the useful DBCC Commands for DBA related to Memory Management within SQL Server. Well,  I’ve seen many DBA’s unaware of the below very useful commands staying under assumption, CHECKDB is the only DBCC Command we’ve in SQL Server.

Okay! Let’s see what do SQL Server offer to DBA’s to do  a diagnosis of SQL Server Memory.

DBCC DROPCLEANBUFFERS : This Command will remove all the Data Pages from the Buffer Cache. Basically, you can issue this if you want to clear your Buffer Cache.

DBCC FREEPROCCACHE: This command will remove all the execution plans from Procedure Cache.

DBCC FREESYSTEMCACHE(‘ALL’) : This command will remove all the Unused entries from all the available caches. It includes Plan cache as well!

DBCC FREESESSIONCACHE : This command will Flush the Distributed Query Connection(Linked Servers) Cache on SQL Instance.

DBCC FLUSHPROCINDB(DB_ID) : This is a pretty useful command which clears Query Plans related to a given Database.
Note: This is an Undocumented Command. 

Hope this is useful! Be very cautious and understand what you are doing before issuing these Commands blindly on your Production SQL Instances to resolve an issue, especially on an Instance which is shared by Multiple applications with many Databases.

The EXECUTE permission was denied on the object ‘xp_prop_oledb_provider’, database ‘mssqlsystemresource’

Today I was setting up a Linked Server from one SQL Server 2008R2 Instance to another SQL Server 2005 Instance with one of the Databases as a Catalog and I was able to create the Linked Server and Tested it successfully, but the Developer was getting an annoying Error as shown below…

The EXECUTE permission was denied on the object ‘xp_prop_oledb_provider’, database ‘mssqlsystemresource’, schema ‘sys’. (.Net SqlClient Data Provider)

What does it mean? It is complaining about a missing permission from Resource Database, which really can’t be touched by any means in terms of Permissions from our SSMS. ( Remember, Resource DB can be accessed just from File System as mdf and ldf files from your Binaries Folder)

So, how to fix this annoying Error?

My Scenario:

1. I’ve a created  a Linked Server using “Microsoft OLEDB Provider for SQL Server” as  Provider by choosing Server type as Other Provider  instead of going with SQL Server. Don’t ask me why 😀

2. I’ve logged in as a user which is not a SysAdmin and when i try to expand the Catalogs from Linked Server I got  this below error message, as you can see in below Screenshot.

Please note I’ve logged in using login “Linked” – I’ve created a test login called “Linked” for this Demo Purpose…

How to Fix this?

1.Map the User to MASTER Database( By Def. It will be added to Public Role)

2.USE MASTER

GO

GRANT EXECUTE ON SYS.XP_PROP_OLEDB_PROVIDER TO LOGIN;

Once, I did this, I’m able to access the Linked Server without any Issues as you can see below…

Howdyyyyyyy! Hope this helps

How to Create a Suspect Database???….

Yes, You heard it right! How to Create a SUSPECT Database. You might be thinking, why would someone make a Database Suspect! I got you! Well, This post is not to teach you how to make your Production Database as “SUSPECT” 😉  I thought of sharing this Info, to fight a PANIC situation where you see a SUSPECT Database in your environment.  Create a SUSPECT Database in your play area and practice how to recover from that situation, get familiarize with a SUSPECT DB and play with it and try to recover from it far before a real Disaster hits your Prod Database(I hope not).

In this post, I’m not going to show how to recover from “SUSPECT DB”, Instead just to simulate a scenario where your DB goes into SUSPECT State. Let’s begin!!!…

Couple of months ago, I’ve written a small blog post(see here) on how to simulate 824 Error using Hex Editor. I’ll be using the same tool to achieve our goal here in this post.

Simple Method:

Step 1: Create a Dummy Database to play with.

Step 2 : Shutdown your SQL Server DB Engine Service.

Step 3: Open your LDF file with Hex Editor and edit it manually with few Bogus entries.

Step 4: Start your SQL Instance, you should be seeing your Database marked as Suspect by SQL Server.

Alternate, more practical method:

Step 1: I’ve created a dummy database to play with “Suspect_tst”.

Step2: I’ve started an explicit transaction(but didn’t committed or Rolled Back) and left it as an Open transaction and did a Checkpoint.

Step3: Force Shut down your SQL Server.

Step4: Open your ldf file in Hex Editor and choose a random row and fill them with some random bogus values same as in method 1.

Step5: Start your SQL Server, You will be seeing a Suspect Database 🙂

You can see the below Screenshot what i meant in Steps 1 and 2.

Now, as of Step 3, all you’ve to do is just open a new query and type “SHUTDOWN  WITH NOWAIT;“(Never ever run this on Production, Trust me, you’ll immediately loose your job:D)

for Step 5, as you can see in the below screenshot, I’ve opened ldf file and filled in 2nd Row with all 1’s.

Save and now Start your SQL Server Instance! Once SQL has been started, query your DB Status as shown below.

Tadaaaaa! We did it….:)

Now, you know how to simulate this most disastrous situation, play with this database for recovery, loosing as less amount data as you can. Cheers!

SQL Server 2008 SP3 Released……….:)

Microsoft SQL Server 2008 Service Pack3 Released:

Howdy!! Microsoft has released Service Pack3 for SQL Server 2008. This contains CU 1 to 4 of SQL Server 2008 SP2 + few interesting fixes to issues which customers have repeated.

As per MSFT, Few Interesting Enhancements in this SP are:

  • Enhanced Warning messages when we create any Maintenance Plan with Shrink DB           Option Enabled! Yayyyyyyy…… 🙂
  • Exact Number of rows sent in Data Flows will be logged in SSIS logs .
  • Increased and Reliable Setup experience/performance.
  • Making Database Enabled in the case of dropping your Certificates!! (It doesn’t mean that you can loose your Certificates, after all they are the most Critical pieces of the Encryption Puzzle)

For More Information and downloading/testing yourself , Please visit Microsoft Download Center.

http://www.microsoft.com/download/en/details.aspx?displaylang=en&id=27594

SQL Server CheckPoints – Trace Flag 3502

Checkpoint – One of the wonderful mechanisms baked within SQL Server to Flush Dirty Pages to Disk and to clear Transaction log(When a Database is Set to SIMPLE Recovery Model) automatically.

Few scenarios where CHECKPOINTS are triggered automatically:

When SQL Instance has been Shutdown, a checkpoint on all the databases.

A Checkpoint on Model Database each time a new database has been created.

T-Log 70% full and Database is in Simple Recovery Model.

A Manual CHECKPOINT by a Sysadmin or Database Owner/Backup Operator.

So…Is there any easy way to monitor the occurrences of Checkpoint??

Yes…We’ve a Documented Trace Flag 3502 which can be enabled Globally.

Demo: Scenario 1 – Shutting Down SQL Instance

I’ve enabled 3502 Traceflag and shut down my SQL Instance. See the Error Log contents below.

2011-09-19 22:12:08.200 spid52 Microsoft SQL Server 2008 R2 (SP1) – 10.50.2425.0 (X64)
Apr 6 2011 21:03:25
Copyright (c) Microsoft Corporation
Developer Edition (64-bit) on Windows NT 6.1 <X64> (Build 7601: Service Pack 1)
2011-09-19 22:12:08.210 spid52 (c) Microsoft Corporation.
2011-09-19 22:12:08.210 spid52 All rights reserved.
2011-09-19 22:12:08.210 spid52 Server process ID is 1968.
2011-09-19 22:12:08.210 spid52 System Manufacturer: ‘Dell Inc.’, System Model: ‘Studio 1555’.
2011-09-19 22:12:08.210 spid52 Authentication mode is MIXED.
2011-09-19 22:12:08.220 spid52 Logging SQL Server messages in file ‘C:\Program Files\Microsoft SQL Server\MSSQL10_50.PROD\MSSQL\Log\ERRORLOG’.
2011-09-19 22:12:08.220 spid52 The error log has been reinitialized. See the previous log for older entries.
2011-09-19 22:12:29.830 spid52 DBCC TRACEON 3502, server process ID (SPID) 52. This is an informational message only; no user action is required.
2011-09-19 22:13:09.050 spid7s Checkpointing and truncating dbid 1 (master).
2011-09-19 22:13:09.060 spid7s Ckpt dbid 1 started (8)
2011-09-19 22:13:09.060 spid7s About to log Checkpoint begin.
2011-09-19 22:13:09.100 spid7s Ckpt dbid 1 phase 1 ended (8)
2011-09-19 22:13:09.130 spid7s About to log Checkpoint end.
2011-09-19 22:13:09.140 spid7s Ckpt dbid 1 complete
2011-09-19 22:13:09.140 spid7s Checkpointing and truncating dbid 2 (tempdb).
2011-09-19 22:13:09.140 spid7s About to log Checkpoint begin.
2011-09-19 22:13:09.160 spid7s About to log Checkpoint end.
2011-09-19 22:13:09.200 spid7s No checkpoint needed on dbid 3 (model).
2011-09-19 22:13:09.200 spid7s Checkpointing and truncating dbid 4 (msdb).
2011-09-19 22:13:09.220 spid7s Ckpt dbid 4 started (8)
2011-09-19 22:13:09.220 spid7s About to log Checkpoint begin.
2011-09-19 22:13:09.220 spid7s Ckpt dbid 4 phase 1 ended (8)
2011-09-19 22:13:09.260 spid7s About to log Checkpoint end.
2011-09-19 22:13:09.310 spid7s Ckpt dbid 4 complete
2011-09-19 22:13:09.350 spid7s No checkpoint needed on dbid 5 (LiteSpeedLocal).
2011-09-19 22:13:09.360 spid7s No checkpoint needed on dbid 6 (LiteSpeedCentral).
2011-09-19 22:13:09.730 spid7s No checkpoint needed on dbid 8 (AdventureWorksDW2008R2).
2011-09-19 22:13:09.780 spid7s No checkpoint needed on dbid 9 (AdventureWorksLT2008R2).
2011-09-19 22:13:09.910 spid7s Checkpointing and truncating dbid 10 (AdventureWorks).
2011-09-19 22:13:09.910 spid7s Ckpt dbid 10 started (8)
2011-09-19 22:13:09.930 spid7s About to log Checkpoint begin.
2011-09-19 22:13:09.930 spid7s Ckpt dbid 10 phase 1 ended (8)
2011-09-19 22:13:09.930 spid7s About to log Checkpoint end.
2011-09-19 22:13:09.980 spid7s Ckpt dbid 10 complete
2011-09-19 22:13:10.000 spid7s No checkpoint needed on dbid 11 (AdventureWorksDW).
2011-09-19 22:13:10.030 spid7s Checkpointing and truncating dbid 12 (AdventureWorksLT).
2011-09-19 22:13:10.030 spid7s Ckpt dbid 12 started (8)
2011-09-19 22:13:10.060 spid7s About to log Checkpoint begin.
2011-09-19 22:13:10.070 spid7s Ckpt dbid 12 phase 1 ended (8)
2011-09-19 22:13:10.070 spid7s About to log Checkpoint end.
2011-09-19 22:13:10.120 spid7s Ckpt dbid 12 complete
2011-09-19 22:13:10.150 spid7s Checkpointing and truncating dbid 13 (AdventureWorks_11).
2011-09-19 22:13:10.150 spid7s Ckpt dbid 13 started (8)
2011-09-19 22:13:10.150 spid7s About to log Checkpoint begin.
2011-09-19 22:13:10.170 spid7s Ckpt dbid 13 phase 1 ended (8)
2011-09-19 22:13:10.170 spid7s About to log Checkpoint end.
2011-09-19 22:13:10.210 spid7s Ckpt dbid 13 complete
2011-09-19 22:13:10.220 spid7s Checkpointing and truncating dbid 14 (AdventureWorks_tstst).
2011-09-19 22:13:10.220 spid7s Ckpt dbid 14 started (8)
2011-09-19 22:13:10.230 spid7s About to log Checkpoint begin.
2011-09-19 22:13:10.230 spid7s Ckpt dbid 14 phase 1 ended (8)
2011-09-19 22:13:10.240 spid7s About to log Checkpoint end.
2011-09-19 22:13:10.280 spid7s Ckpt dbid 14 complete
2011-09-19 22:13:10.300 spid7s No checkpoint needed on dbid 15 (AdventureWorks_testst).
2011-09-19 22:13:10.320 spid7s No checkpoint needed on dbid 16 (tstrestore).
2011-09-19 22:13:10.350 spid7s Checkpointing and truncating dbid 17 (ReportServer).
2011-09-19 22:13:10.350 spid7s Ckpt dbid 17 started (8)
2011-09-19 22:13:10.350 spid7s About to log Checkpoint begin.
2011-09-19 22:13:10.370 spid7s Ckpt dbid 17 phase 1 ended (8)
2011-09-19 22:13:10.370 spid7s About to log Checkpoint end.
2011-09-19 22:13:10.420 spid7s Ckpt dbid 17 complete
2011-09-19 22:13:10.450 spid7s Checkpointing and truncating dbid 18 (ReportServerTempDB).
2011-09-19 22:13:10.450 spid7s Ckpt dbid 18 started (8)
2011-09-19 22:13:10.480 spid7s About to log Checkpoint begin.
2011-09-19 22:13:10.500 spid7s Ckpt dbid 18 phase 1 ended (8)
2011-09-19 22:13:10.500 spid7s About to log Checkpoint end.
2011-09-19 22:13:10.550 spid7s Ckpt dbid 18 complete
2011-09-19 22:13:10.570 spid7s Checkpointing and truncating dbid 19 (3014_demo).
2011-09-19 22:13:10.570 spid7s Ckpt dbid 19 started (8)
2011-09-19 22:13:10.580 spid7s About to log Checkpoint begin.
2011-09-19 22:13:10.590 spid7s Ckpt dbid 19 phase 1 ended (8)
2011-09-19 22:13:10.600 spid7s About to log Checkpoint end.
2011-09-19 22:13:10.630 spid7s Ckpt dbid 19 complete
2011-09-19 22:13:10.630 spid7s Checkpointing and truncating dbid 32767 (mssqlsystemresource).
2011-09-19 22:13:11.160 spid14s Service Broker manager has shut down.
2011-09-19 22:13:11.250 spid7s Skipping CleanShutdownDB() checkpoint on dbid 19 (3014_demo) with 0 freedOutcomes.
2011-09-19 22:13:11.640 spid7s Skipping CleanShutdownDB() checkpoint on dbid 18 (ReportServerTempDB) with 0 freedOutcomes.
2011-09-19 22:13:11.740 spid7s Skipping CleanShutdownDB() checkpoint on dbid 17 (ReportServer) with 0 freedOutcomes.
2011-09-19 22:13:11.850 spid7s Ckpt dbid 16 started (8)
2011-09-19 22:13:11.850 spid7s About to log Checkpoint begin.
2011-09-19 22:13:11.870 spid7s Ckpt dbid 16 phase 1 ended (8)
2011-09-19 22:13:11.890 spid7s About to log Checkpoint end.
2011-09-19 22:13:11.920 spid7s Ckpt dbid 16 complete
2011-09-19 22:13:12.050 spid7s Skipping CleanShutdownDB() checkpoint on dbid 15 (AdventureWorks_testst) with 0 freedOutcomes.
2011-09-19 22:13:12.180 spid7s Skipping CleanShutdownDB() checkpoint on dbid 14 (AdventureWorks_tstst) with 0 freedOutcomes.
2011-09-19 22:13:12.280 spid7s Skipping CleanShutdownDB() checkpoint on dbid 13 (AdventureWorks_11) with 0 freedOutcomes.
2011-09-19 22:13:12.390 spid7s Skipping CleanShutdownDB() checkpoint on dbid 12 (AdventureWorksLT) with 0 freedOutcomes.
2011-09-19 22:13:12.480 spid7s Ckpt dbid 11 started (8)
2011-09-19 22:13:12.480 spid7s About to log Checkpoint begin.
2011-09-19 22:13:12.510 spid7s Ckpt dbid 11 phase 1 ended (8)
2011-09-19 22:13:12.530 spid7s About to log Checkpoint end.
2011-09-19 22:13:12.560 spid7s Ckpt dbid 11 complete
2011-09-19 22:13:12.690 spid7s Skipping CleanShutdownDB() checkpoint on dbid 10 (AdventureWorks) with 0 freedOutcomes.
2011-09-19 22:13:12.860 spid7s Ckpt dbid 9 started (8)
2011-09-19 22:13:12.860 spid7s About to log Checkpoint begin.
2011-09-19 22:13:12.900 spid7s Ckpt dbid 9 phase 1 ended (8)
2011-09-19 22:13:12.920 spid7s About to log Checkpoint end.
2011-09-19 22:13:12.950 spid7s Ckpt dbid 9 complete
2011-09-19 22:13:13.180 spid7s Ckpt dbid 8 started (8)
2011-09-19 22:13:13.180 spid7s About to log Checkpoint begin.
2011-09-19 22:13:13.200 spid7s Ckpt dbid 8 phase 1 ended (8)
2011-09-19 22:13:13.220 spid7s About to log Checkpoint end.
2011-09-19 22:13:13.270 spid7s Ckpt dbid 8 complete
2011-09-19 22:13:13.410 spid7s Ckpt dbid 6 started (8)
2011-09-19 22:13:13.410 spid7s About to log Checkpoint begin.
2011-09-19 22:13:13.460 spid7s Ckpt dbid 6 phase 1 ended (8)
2011-09-19 22:13:13.480 spid7s About to log Checkpoint end.
2011-09-19 22:13:13.510 spid7s Ckpt dbid 6 complete
2011-09-19 22:13:13.640 spid7s Ckpt dbid 5 started (8)
2011-09-19 22:13:13.640 spid7s About to log Checkpoint begin.
2011-09-19 22:13:13.660 spid7s Ckpt dbid 5 phase 1 ended (8)
2011-09-19 22:13:13.670 spid7s About to log Checkpoint end.
2011-09-19 22:13:13.710 spid7s Ckpt dbid 5 complete
2011-09-19 22:13:13.880 spid7s Ckpt dbid 4 started (8)
2011-09-19 22:13:13.880 spid7s About to log Checkpoint begin.
2011-09-19 22:13:13.880 spid7s Ckpt dbid 4 phase 1 ended (8)
2011-09-19 22:13:13.890 spid7s About to log Checkpoint end.
2011-09-19 22:13:13.890 spid7s Ckpt dbid 4 complete
2011-09-19 22:13:14.000 spid7s Skipping CleanShutdownDB() checkpoint on dbid 3 (model) with 0 freedOutcomes.
2011-09-19 22:13:14.140 spid7s Ckpt dbid 1 started (8)
2011-09-19 22:13:14.140 spid7s About to log Checkpoint begin.
2011-09-19 22:13:14.140 spid7s Ckpt dbid 1 phase 1 ended (8)
2011-09-19 22:13:14.140 spid7s About to log Checkpoint end.
2011-09-19 22:13:14.140 spid7s Ckpt dbid 1 complete
2011-09-19 22:13:14.140 spid7s SQL Server is terminating in response to a ‘stop’ request from Service Control Manager. This is an informational message only. No user action is required.
2011-09-19 22:13:14.180 spid7s SQL Trace was stopped due to server shutdown. Trace ID = ‘1’. This is an informational message only; no user action is required.
Sooo….SQL Server is making sure that a CHECKPOINT is issued on all the Databases as mentioned above before Shutting down the SQL Instance.( Which plays a huge and a very critical role in crash recovery when SQL Instance has been started)

Scenario 2- Creating a new User Database:

I’ve created a Database called “Checkpoint_tst”. See the Error Log contents below.

2011-09-19 22:18:58.020 spid53 Microsoft SQL Server 2008 R2 (SP1) – 10.50.2425.0 (X64)
Apr 6 2011 21:03:25
Copyright (c) Microsoft Corporation
Developer Edition (64-bit) on Windows NT 6.1 <X64> (Build 7601: Service Pack 1)
2011-09-19 22:18:58.020 spid53 (c) Microsoft Corporation.
2011-09-19 22:18:58.020 spid53 All rights reserved.
2011-09-19 22:18:58.020 spid53 Server process ID is 9120.
2011-09-19 22:18:58.020 spid53 System Manufacturer: ‘Dell Inc.’, System Model: ‘Studio 1555’.
2011-09-19 22:18:58.020 spid53 Authentication mode is MIXED.
2011-09-19 22:18:58.020 spid53 Logging SQL Server messages in file ‘C:\Program Files\Microsoft SQL Server\MSSQL10_50.PROD\MSSQL\Log\ERRORLOG’.
2011-09-19 22:18:58.020 spid53 The error log has been reinitialized. See the previous log for older entries.
2011-09-19 22:18:58.020 spid53 DBCC TRACEON 3502, server process ID (SPID) 53. This is an informational message only; no user action is required.
2011-09-19 22:20:11.500 spid53 Ckpt dbid 3 started (8)
2011-09-19 22:20:11.500 spid53 About to log Checkpoint begin.
2011-09-19 22:20:11.510 spid53 Ckpt dbid 3 phase 1 ended (8)
2011-09-19 22:20:11.510 spid53 About to log Checkpoint end.
2011-09-19 22:20:11.520 spid53 Ckpt dbid 3 complete
2011-09-19 22:20:11.790 spid53 Starting up database ‘checkpoint_tst’.
2011-09-19 22:20:11.840 spid53 Ckpt dbid 20 started (0)
2011-09-19 22:20:11.840 spid53 About to log Checkpoint begin.
2011-09-19 22:20:11.840 spid53 Ckpt dbid 20 phase 1 ended (0)
2011-09-19 22:20:11.840 spid53 About to log Checkpoint end.
2011-09-19 22:20:11.840 spid53 Ckpt dbid 20 complete
2011-09-19 22:20:55.860 spid11s About to log Checkpoint begin.
2011-09-19 22:20:55.870 spid11s About to log Checkpoint end.

(22 row(s) affected)

dbid= 3 is MODEL Database. You can pull that info by

select name,database_id from sys.databases
where database_id = 3

Hope this is informative!

Backup Internals – Trace Flag 3014

Trace Flag 3014–  This is one of the undocumented Trace flags in SQL Server, which basically gives a detailed information(Well, This might not be useful in most of the cases) regarding File Creation, Padding and much more related Info while you are taking a Backup of your Database.

Do you really need this Info? IMHO, 95% of the cases, i would say NO. I consider this as Just an FYI kind of Information. When i try to troubleshoot Backup/Restore Issues, I rather enable Trace Flags 3004 and 3014 along with 3605(to enable logging of all the entries in our Error Log) instead of Just enabling Single Flag(Make sure you disable these Flags once you are done with diagnostics).

Let’s See what exactly get’s logged when i Enable these Trace Flags and Take a Full Database Backup.

Tadaaaaaaaaaa!
2011-09-15 22:00:40.470 spid54 BackupStream(0): Starting MSDA of size 384 extents
2011-09-15 22:00:40.470 spid54 Started file C:\Program Files\Microsoft SQL Server\MSSQL10_50.PROD\MSSQL\DATA\3014_demo.mdf
2011-09-15 22:00:40.780 spid54 Completed file C:\Program Files\Microsoft SQL Server\MSSQL10_50.PROD\MSSQL\DATA\3014_demo.mdf
2011-09-15 22:00:40.790 spid54 Padding MSDA with 327680 bytes
2011-09-15 22:00:40.790 spid54 BackupStream(0): Total MSDA: 384 extents
2011-09-15 22:00:40.860 Backup Database backed up. Database: 3014_demo, creation date(time): 2011/09/15(21:46:19), pages dumped: 3100, first LSN: 163:1808:37, last LSN: 163:1824:1, number of dump devices: 1, device information: (FILE=2, TYPE=DISK: {‘D:\Backs\3014_full.bak’}).

So..Basically you can see exact times while starting backup stream , how many Extents being affected, what file(s) etc…Again This is Just an FYI information in most of the cases while you are dealing with Backups, where as the Trace Flag 3004(see here) is Extremely Useful while investigating DB Restore Issues. YMMV!