ASE Database forum - HK GC causing a lot of physical reads / disk I/O ... and is not shown on MDA tables ???

Author

HK GC causing a lot of physical reads / disk I/O ... and is not shown on MDA tables ???

Jesus M. Salvo Jr.

2005-10-27, 8:21 am

Adaptive Server Enterprise/12.5.3/EBF 12330 ESD#1/P/Sun_svr4/OS 5.8/ase1253/1900/32-bit/FBO/Tue Jan 25 07:02:08 2005

I have "enable housekeeper GC" set to 4.

I was running sp_sysmon 'hh:mm:ss', 'cache wizard',
and there was one specific table that has a very high number of physical reads / second,
with snippet shown below:

====================
====================
====================
====================

Cache Wizard
====================
====================
====================
====================

------------------
default data cache
------------------
Run Size : 128.00 Mb Usage% : 86.81
LR/sec : 6705.10 PR/sec : 941.80 Hit%: 85.95
Cache Partitions: 2 Spinlock Contention%: 0.00

Buffer Pool Information
--------------------------------------------------------------------------------
IO Size Wash Size Run Size APF% LR/sec PR/sec Hit% APF-Eff% Usage%
------- ---------- ----------- ------ -------- -------- ------ -------- ------
32 Kb 6528 Kb 32.00 Mb 10.00 646.90 20.50 96.83 0.00 45.04
4 Kb 19656 Kb 96.00 Mb 10.00 6058.20 921.30 84.79 0.00 100.74

(1 row affected)

Object Statistics
--------------------------------------------------------------------------------

Object LR/sec PR/sec Hit% Obj_Cached% Cache_Occp%
----------------------------------------------------------------------- ------- ------- ------ ----------- -----------
sgmaster.dbo. message_notification
_history. notification_send_id
x 908.50 890.10 2.03 2.61 71.02
sgmaster.dbo.player_to_game 70.40 20.30 71.16 29.19 23.35
sgmaster.dbo. message_notification
_history. notification_protoco
lmsid_idx 28.00 0.50 98.21 0.01 0.13
sgmaster.dbo. message_notification
_history. message_notification
_pk 18.80 0.40 97.87 0.00 0.03

You can see from the above that there is a very high PR/sec on the index notification_send_id
x.

Now to find out what is causing it:

1) I queried monProcessStatement:

select s.SPID, s.PhysicalReads, s.LogicalReads, t.LineNumber, t.SQLText
from monProcessStatement s, monProcessSQLText t
where s.SPID=t.SPID
order by s.PhysicalReads desc, s.LogicalReads desc, s.SPID, t.LineNumber

SPID PhysicalReads LogicalReads LineNumber SQLText
------ ------------- ------------ ----------- ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-----------------------------------------------
96 0 9 1 select s.SPID, s.PhysicalReads, s.LogicalReads, t.LineNumber, t.SQLText
96 0 9 2 from monProcessStatement s, monProcessSQLText t
96 0 9 3 where s.SPID=t.SPID
96 0 9 4 order by s.PhysicalReads desc, s.LogicalReads desc, s.SPID, t.LineNumber
96 0 9 5

hmmm ... not there. Maybe I have the wrong join. Just check monProcessStatement:

1> select s.SPID, s.PhysicalReads, s.LogicalReads
from monProcessStatement s
order by s.PhysicalReads desc, s.LogicalReads desc, s.SPID2> 3>
4> go
SPID PhysicalReads LogicalReads
------ ------------- ------------
44 0 9

(1 row affected)

hmmm ... not there.

2) I tried monProcessObject:

1> select o.SPID, o.LogicalReads, o.PhysicalReads, o.PhysicalAPFReads,
o.ObjectName, o.ObjectType
from monProcessObject o2> 3>
4> go
SPID LogicalReads PhysicalReads PhysicalAPFReads ObjectName ObjectType
------ ------------ ------------- ---------------- ------------------------------ ------------------------------
96 0 0 0 monProcessObject user table

(1 row affected)

...... not there either

3) Then by chance, I looked at sp_lock:

1> sp_lock
2> go
The class column will display the cursor name for locks associated with a cursor for the current user and the cursor id for other users.
fid spid loid locktype table_id page row dbname class context
------ ------ ----------- ---------------------------- ----------- ----------- ------ --------------- ------------------------------ ----------------------------
0 6 12 Ex_intent 1915150837 0 0 sgmaster Non Cursor Lock
0 96 192 Sh_intent 32000114 0 0 master Non Cursor Lock

(2 rows affected)
(return status = 0)

.... and then checked what table was SPID 6 was using:

1> use sgmaster
2> go
1> select object_name( 1915150837 )
2> go

------------------------------
message_notification
_history

(1 row affected)

Aahhh!!
and what was spid 6 ( HK GC ):

1> sp_who
2> go
fid spid status loginame origname hostname blk_spid dbname cmd block_xloid
------ ------ ------------ ------------------------------ ------------------------------ ---------- -------- ------------------------------ ---------------- -----------
0 2 sleeping NULL NULL 0 master DEADLOCK TUNE 0
0 3 sleeping NULL NULL 0 master ASTC HANDLER 0
0 4 sleeping NULL NULL 0 master CHECKPOINT SLEEP 0
0 5 sleeping NULL NULL 0 master HK WASH 0
0 6 sleeping NULL NULL 0 master HK GC 0

Now questions are:

====================
===========
1) Why isn't the MDA tables ( monProcessObject and monProcessStatement in particular )
not showing the HK GC process, when it was doing a lot of physical I/O ??

OK, I can see the physical reads from monProcessActivity ( see below ), but not from the other tables ..
and one cannot know which object the SPID is doing a lot of I/O on:

1> select SPID, PhysicalReads, LogicalReads, TableAccesses, IndexAccesses
from monProcessActivity where SPID = 6
order by PhysicalReads desc2> 3>
4> go
SPID PhysicalReads LogicalReads TableAccesses IndexAccesses
------ ------------- ------------ ------------- -------------
6 136677583 270989372 599 0

(1 row affected)
1> select SPID, PhysicalReads, LogicalReads, TableAccesses, IndexAccesses
from monProcessActivity where SPID = 6
order by PhysicalReads desc2> 3>
4> go
SPID PhysicalReads LogicalReads TableAccesses IndexAccesses
------ ------------- ------------ ------------- -------------
6 136680459 270994844 599 0

2) Is this normal behaviour ( the physical read ), particularly after a reorg rebuild on the index AND / OR an update index statistics ??

Thanks

Jesus M. Salvo Jr.

2005-10-27, 8:21 am

Jesus M. Salvo Jr. wrote:

>
> Now questions are:
>
> ====================
===========
> 1) Why isn't the MDA tables ( monProcessObject and monProcessStatement in
> particular ) not showing the HK GC process, when it was doing a lot of
> physical I/O ??
>

Forgot ... here's the relevant output from sp_sysmon:

====================
====================
====================
===================

Housekeeper Task Activity
-------------------------
per sec per xact count % of total
------------ ------------ ----------
Buffer Cache Washes
Clean 209.1 5.2 6274 96.0 %
Dirty 8.7 0.2 262 4.0 %
------------ ------------ ----------
Total Washes 217.9 5.5 6536

Garbage Collections 0.1 0.0 2 n/a
Pages Processed in GC 0.0 0.0 0 n/a

Statistics Updates 3.0 0.1 90 n/a

====================
====================
====================
===================

Stefan Karlsson

2005-10-27, 8:21 am

"Jesus M. Salvo Jr." <noone@noone.org> wrote in message
news:43550269@forums
-1-dub...
> Jesus M. Salvo Jr. wrote:
>
in[color=darkred]
>
>
> Forgot ... here's the relevant output from sp_sysmon:
>
>
====================
====================
====================
================
===
>
> Housekeeper Task Activity
> -------------------------
> per sec per xact count % of
total

> ------------ ------------ ----------
> Buffer Cache Washes
> Clean 209.1 5.2 6274
96.0 %
> Dirty 8.7 0.2 262
4.0 %
> ------------ ------------ ----------
> Total Washes 217.9 5.5 6536

This is HK Wash, a low prio background task that writes dirty buffers to
disk to alleviate checkpoint.

>
> Garbage Collections 0.1 0.0 2
n/a

This is HK GC, and has successfully processed 0.1 pages per second.

HTH,

/Stefan

Jesus M. Salvo Jr.

2005-10-27, 8:21 am

Stefan Karlsson wrote:

>
> "Jesus M. Salvo Jr." <noone@noone.org> wrote in message
> news:43550269@forums
-1-dub...
====================
====================
====================
================[col
or=darkred]
> ===
> total
> 96.0 %
> 4.0 %
>
> This is HK Wash, a low prio background task that writes dirty buffers to
> disk to alleviate checkpoint.
>
> n/a
>
> This is HK GC, and has successfully processed 0.1 pages per second.
>
> HTH,
>
> /Stefan[/color]

Yes ... I know that.
I does not explain the behaviour that I am seeing though.

Jesus M. Salvo Jr.

2005-10-27, 8:21 am

Jesus M. Salvo Jr. wrote:

>
> Adaptive Server Enterprise/12.5.3/EBF 12330 ESD#1/P/Sun_svr4/OS
> 5.8/ase1253/1900/32-bit/FBO/Tue Jan 25 07:02:08 2005
>
>
>
> I have "enable housekeeper GC" set to 4.
>

I reset "enable housekeeper GC" to 1 ... and HK GC stopped doing that having
read physical I/O on the index. It was running since on that same index
since at least yesterday!

Jesus M. Salvo Jr.

2005-10-27, 8:21 am

Jesus M. Salvo Jr. wrote:

> Jesus M. Salvo Jr. wrote:
>
>
> I reset "enable housekeeper GC" to 1 ... and HK GC stopped doing that
> having read physical I/O on the index. It was running since on that same
> index since at least yesterday!

Resetting "enable housekeeper GC" to either 4 or 5 exhibits the behaviour
that I was seeing.

Sponsored Links