2017-09-25

digging into mrskew internals

I'm spending some time working with Method-Rs trace file analyzer mrskew.
As the requirements are beyond simple analyses (here an example about the uncommon things to do) I'm consulting the documentation and all available information in detail. After many readings I started to take this part of the documentation serious:

EXPRESSIONS
Wherever mrskew requires an expression (such as in --group and --where option arguments), you may use any valid Perl expression consisting of:
Perl operators
Operators such as or xor and not , = ?: || && | ^ < > <= >= lt gt le ge == != <=> eq ne cmp + - . * / % =~ !~ ! ~ ** ...and so on. See http://perldoc.perl.org/perlop.html for details.
Perl builtin functions
Functions such as lc uc s/// int join split sprintf substr ...and so on. See http://perldoc.perl.org/perlfunc.html for details.
File::Basename functions
The functions fileparse, basename, and dirname. See http://perldoc.perl.org/File/Basename.html for details.
mrskew expression variables
Any of the variable names described in "EXPRESSION VARIABLES".
For more information about Perl expression syntax, see http://perldoc.perl.org/perl.html#Tutorials.

It's written "any valid Perl expression" and Jeff showed me a very clever example on StackOverflow. But that's not the end, it raised some questions:
Where in the work of mrskew is the specific expression executed?
What's the order of these expressions?
Can they interact?

A small testcase can answer some of these questions.

I used a very simple artificial tracefile:
Oracle Release 11.2
PARSING IN CURSOR #1 len=20 dep=0 uid=7 oct=6 lid=7 tim=2 hv=1 ad='1' sqlid='A'
insert
END OF STMT

EXEC #1:c=1,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=100
EXEC #1:c=2,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=6,tim=400

a small rc file (rc file is used here to store parameters whenever it's boring to type them on command line):
--init='
 my $trace_string = "trace: ";
 my $test_string;
    sub xfrm {
   if ($_[0] eq "where0") {
     $test_string = $test_string . "x";}
   if ($_[0] eq "where1") {
     $test_string =~ s/x/u/g ;}  
      $trace_string = $trace_string . "$_[0]" . "{ $test_string } " . "[$line] -> ";
   
   if ($_[0] eq "group") {
     return $trace_string;}
  else {
    return $_[1]}
    }
'

this uses the --init parameter:
--init=stringExecute string, which must contain syntactically correct Perl code, before beginning file processing. The default value is --init=''.
There I'm setting 2 variables which will be used later.
Also a function xfrm is defined. Depending of the 1st parameter it does different things, always it extends the variable $trace_string with some additional parameters. When the 1st parameter is "group", this $trace_string is returned - my dirty hack for a print of a debug value.

Checking the manpage where an expression ls allowed for a parameter gives me this execution:
(slightly modified for better readability

mrskew --rc martin3.rc  \
  --select='xfrm( "select", 1)' \
  --where0='xfrm( "where0", 1)==1' \
  --where1='xfrm( "where1", 1)==1' \
  --group='xfrm( "group",1)' \
  berx2.trc

The idea is simple: wherever a expression is allowed, my generic function xfrm is called with the name of the mrskew-parameter as it's 1st parameter.

It's result provides some interesting insights:
Summary information by file (modified)
mrskew --rc martin3.rc  --select='xfrm( "select", 1)' --where0='xfrm( "where0", 1)==1' --where1='xfrm( "where1", 1)==1' --group='xfrm( "group",1)' berx2.trc "D:\TEMP\berx2.trc"
Run began 2017-09-25T09:54:40, lasted 0,445000 seconds

input files:
 'D:\TEMP\berx2.trc'

where expression:
 ((xfrm( "where0", 1)==1) and (xfrm( "where1", 1)==1)) and ($nam=~/(?^:(?i).+)/)

group expression:
 xfrm( "group",1)

matched call names:
 'EXEC'

'xfrm( "group",1)'                                                                                                                                                                                                                                                                                                 'xfrm( "select", 1)'       %  CALLS      MEAN       MIN       MAX
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------  --------------------  ------  -----  --------  --------  --------
trace: where0{ x } [1] -> where1{ u } [1] -> where0{ ux } [4] -> where1{ uu } [4] -> where0{ uux } [5] -> where1{ uuu } [5] -> where0{ uuux } [6] -> where1{ uuuu } [6] -> select{ uuuu } [6] -> group{ uuuu } [6] ->                                                                                                          1.000000   50.0%      1  1.000000  1.000000  1.000000
trace: where0{ x } [1] -> where1{ u } [1] -> where0{ ux } [4] -> where1{ uu } [4] -> where0{ uux } [5] -> where1{ uuu } [5] -> where0{ uuux } [6] -> where1{ uuuu } [6] -> select{ uuuu } [6] -> group{ uuuu } [6] -> where0{ uuuux } [7] -> where1{ uuuuu } [7] -> select{ uuuuu } [7] -> group{ uuuuu } [7] ->               1.000000   50.0%      1  1.000000  1.000000  1.000000
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------  --------------------  ------  -----  --------  --------  --------
TOTAL (2)                                                                                                                                                                                                                                                                                                                      2.000000  100.0%      2  1.000000  1.000000  1.000000
mrskew: file 'berx2.trc' does not exist

As the $trace_string is quite long I cut it down into pieces and my interpretation:
trace: where0{ x } [1] -> where1{ u } [1] -> 
where0 is called before where1
where1 can modify a variable set by where0 (the x becomes an u).

where0{ ux } [4] -> where1{ uu } [4] -> where0{ uux } [5] -> where1{ uuu } [5] -> 
where0 and where1 are NOT used in lines 2 & 3 of the trace file (PARSING IN CURSOR and the insert statement)

where0{ uuux } [6] -> where1{ uuuu } [6] -> select{ uuuu } [6] -> group{ uuuu } [6] -> 

in line 6 (EXEC) where0, where1, select and group functions are used (in that order)

where0{ uuuux } [7] -> where1{ uuuuu } [7] -> select{ uuuuu } [7] -> group{ uuuuu } [7] ->

the same is true for line 7.

There is probably more to identify as my simplified tracefile did not show all possible lines and their combination. But the possibility to run code inside mrskew at different positions, and even manipulate some values is shown. Even manipulating mrskews own variables might be of some interest, but it must be identified first where/when they are set and changed. This is open for the readers exercise, the method is shown here :-)

2017-09-12

wrong permission on shm kills JAVA_JIT

We found a lot of trace files from several DBs on one of our DB Servers.
They look like:


*********_ora_26444.trc or *********_m000_5598.trc
*** 2017-09-08 15:11:29.181
*** SESSION ID:(632.5995) 2017-09-08 15:11:29.181
*** CLIENT ID:(SYSADMIN) 2017-09-08 15:11:29.181
*** SERVICE NAME:(****_****) 2017-09-08 15:11:29.181
*** MODULE NAME:(*::***:******.****.***.****.******) 2017-09-08 15:11:29.181
*** ACTION NAME:(/) 2017-09-08 15:11:29.181

peshmmap_Create_Memory_Map:
Map_Length = 4096
Map_Protection = 7
Flags = 1
File_Offset = 0
mmap failed with error 1
error message:Operation not permitted

*** 2017-09-08 15:11:29.181
Exception [type: SIGSEGV, Address not mapped to object] [ADDR:0x0] [PC:0x33BEF41, ioc_pin_shared_executable_object()+1509] [flags: 0x0, count: 1]
DDE: Problem Key 'ORA 7445 [ioc_pin_shared_executable_object()+1509]' was flood controlled (0x6) (incident: 61088)
ORA-07445: exception encountered: core dump [ioc_pin_shared_executable_object()+1509] [SIGSEGV] [ADDR:0x0] [PC:0x33BEF41] [Address not mapped to object] []
ssexhd: crashing the process...
Shadow_Core_Dump = PARTIAL
ksdbgcra: writing core file to directory '/***/diag/rdbms/***/***/cdump'

A quick search on MOS (and a opened SR) showedd as top result Ora‑7445 [Ioc_pin_shared_executable_object()] (Doc ID 1316906.1)

But the suggestions there did not solve the issue. (and we could not set java_jit_enabled = false due to application requirements).

But the Note was good enough to make me search more regarding /dev/shm, mmap and Operation not permitted.  This led to Shared executable memory on StackExchange. Again not a perfect fit, but it makes enough sense to guess:
with java_jit_enabled, the m000 process is doing the compilation (in time). To let the server process execute the compiled code, it's put into shared memory in a /tmp/ file and mapped in the private memory [ 2019-11-15 - fixed based on a comment by Nenad Noveljic ].
This shared memory must be executable, otherwise the server process can not use it. So the memory is mapped with PROT_EXEC.
I checked on the affected host, if there is a reason against this:
> mount|grep shm    
tmpfs on /dev/shm type tmpfs (rw,nosuid,nodev,noexec,seclabel)

noexec prevents shared memory to be executed, so the memory mapping fails.

It's stated in Oracle Database Preinstallation Tasks
rw and execute permissions must be set, but noexec and nosuid must not be set.

this was changed after the DBs were installed. Probably for good intentions but with bad effects.

With the proper changes of the mount options, the test statement
SELECT dbms_java.longname('TEST') long_name FROM  dual;
completes without any error.



SecureFile LOB - managing free blocks

This blog post continues with all the objects and settings from SecureFile LOB - the empty tableSecureFile LOB - the 1st insert SecureFile LOB - the 1st update and SecureFile LOB - more inserts.

It starts with some inserts:
insert into berx.TEST_BLOBS
select 4, comments, file_content
from berx.source_blobs
where id=4;

commit;

insert into berx.TEST_BLOBS
select 5, comments, file_content
from berx.source_blobs
where id=1; 

insert into berx.TEST_BLOBS
select 6, comments, file_content
from berx.source_blobs
where id=4; 

insert into berx.TEST_BLOBS
select 7, comments, file_content
from berx.source_blobs
where id=1; 

insert into berx.TEST_BLOBS
select 8, comments, file_content
from berx.source_blobs
where id=4;

insert into berx.TEST_BLOBS
select 9, comments, file_content
from berx.source_blobs
where id=1; 

insert into berx.TEST_BLOBS
select 10, comments, file_content
from berx.source_blobs
where id=4; 

commit;

This leads to 10 lines with 10 LOBs. The LOBs are 1 or 2 blocks in size.

The LOBMAP summary of the rows and LOBs is this:

1 11.1 kB AABu7gAAEAAA+N7AAA

ROWID   = AABu7gAAEAAA+N7AAA
ROWNUM  = 1
LOBID   = 00000001000099BF531D
EXTENT# = 0
rdba   = 17032588 - 0x  103e58c
Block  = 255372
nblks  = 2
offset = 0
length = 11389

2 2-byte AABu7gAAEAAA+N/AAA

ROWID   = AABu7gAAEAAA+N/AAA
ROWNUM  = 2
LOBID   = 00000001000099BF67D1
EXTENT# = 0
rdba   = 17032590 - 0x  103e58e
Block  = 255374
nblks  = 1
offset = 0
length = 2

3 close to 4 kB AABu7gAAEAAA+N/AAB

ROWID   = AABu7gAAEAAA+N/AAB
ROWNUM  = 3
LOBID   = 00000001000099C090E3
EXTENT# = 0
rdba   = 17032587 - 0x  103e58b
Block  = 255371
nblks  = 1
offset = 0
length = 4038

4 11.1 kB AABu7gAAEAAA+N9AAA

ROWID   = AABu7gAAEAAA+N9AAA
ROWNUM  = 4
LOBID   = 00000001000099C56EFB
EXTENT# = 0
rdba   = 17032591 - 0x  103e58f
Block  = 255375
nblks  = 1
offset = 0
length = 8060
---
ROWID   = AABu7gAAEAAA+N9AAA
ROWNUM  = 5
LOBID   = 00000001000099C56EFB
EXTENT# = 1
rdba   = 17033787 - 0x  103ea3b
Block  = 256571
nblks  = 1
offset = 8060
length = 3329

This one is somehow special, as the LOB is 11kB in size, so it requires 2 blocks.
These 2 blocks are spread over 2 tablespace extents (and 2 LOB extents also).
 In this case space optimization won against avoiding fragmentation.

5 1-byte AABu7gAAEAAA+N/AAC

ROWID   = AABu7gAAEAAA+N/AAC
ROWNUM  = 6
LOBID   = 00000001000099C633A9
EXTENT# = 0
rdba   = 17033788 - 0x  103ea3c
Block  = 256572
nblks  = 1
offset = 0
length = 1

6 11.1 kB AABu7gAAEAAA+N/AAD

ROWID   = AABu7gAAEAAA+N/AAD
ROWNUM  = 7
LOBID   = 00000001000099C633AA
EXTENT# = 0
rdba   = 17033789 - 0x  103ea3d
Block  = 256573
nblks  = 2
offset = 0
length = 11389

7 1-byte AABu7gAAEAAA+N/AAE

ROWNUM  = 8
LOBID   = 00000001000099C633AB
EXTENT# = 0
rdba   = 17033791 - 0x  103ea3f
Block  = 256575
nblks  = 1
offset = 0
length = 1

8 11.1 kB AABu7gAAEAAA+N/AAF

ROWNUM  = 9
LOBID   = 00000001000099C633AC
EXTENT# = 0
rdba   = 17033792 - 0x  103ea40
Block  = 256576
nblks  = 2
offset = 0
length = 11389

9 1-byte AABu7gAAEAAA+N/AAG

ROWNUM  = 10
LOBID   = 00000001000099C633AD
EXTENT# = 0
rdba   = 17033794 - 0x  103ea42
Block  = 256578
nblks  = 1
offset = 0
length = 1

10 11.1 kB AABu7gAAEAAA+N/AAH

ROWID   = AABu7gAAEAAA+N/AAH
ROWNUM  = 11
LOBID   = 00000001000099C633AE
EXTENT# = 0
rdba   = 17033795 - 0x  103ea43
Block  = 256579
nblks  = 2
offset = 0
length = 11389

After row 4s commit, the NGLOB: Persistent Undo block changed:

Persistent Undo information

after row 4th commit
Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea05 (4/256517)
scn: 0xa9d.9b8d2fe9 seq: 0x01 flg: 0x04 tail: 0x2fe94001
frmt: 0x02 chkval: 0x39b1 type: 0x40=NGLOB: Persistent Undo
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007FDB0460C800 to 0x00007FDB0460E800
...
  Dump of Persistent Undo Block
  --------------------------------------------------------
 Inst: 1 Objd:454499 Inc:3472328295419215872 SyncTime:4126781815622353101 Flag:0x1
 Total: 2 LoadTime:1505116365 Opcode:1 Xid: 0x01b4.014.00002aca
  --------------------------------------------------------
Chunk: dba: 0x103ea3b: len: 1: Xid:  0x01b4.00d.00002abc: Scn: 2717.-1685245975: Flag: IN USE: FBR: False
Chunk: dba: 0x103ea3c: len: 68: Xid:  0x0000.000.00000000: Scn: 2708.1852084450: Flag: FREE: FBR: False

Block 0x103ea3b is marked as IN USE. This is the 2nd block from the LOB just inserted.
The remaining blocks in this LOB extent are marked as FREE.

After the other 6 inserts, some meta information changed again:

Persistent Undo information

after row 10th commit
Block dump from disk:
buffer tsn: 4 rdba: 0x0103ea05 (4/256517)
scn: 0xa9d.9d4b7340 seq: 0x01 flg: 0x04 tail: 0x73404001
frmt: 0x02 chkval: 0x5850 type: 0x40=NGLOB: Persistent Undo
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007F880DC72800 to 0x00007F880DC74800
...
  Dump of Persistent Undo Block
  --------------------------------------------------------
 Inst: 1 Objd:454499 Inc:3472328295419215872 SyncTime:3473457525430831671 Flag:0x1
 Total: 5 LoadTime:1505118775 Opcode:1 Xid: 0x01af.000.00003334
  --------------------------------------------------------
Chunk: dba: 0x103ea3c: len: 1: Xid:  0x01af.021.00003338: Scn: 2717.-1655999709: Flag: IN USE: FBR: False
Chunk: dba: 0x103ea3d: len: 2: Xid:  0x01af.021.00003338: Scn: 2717.-1655999697: Flag: IN USE: FBR: False
Chunk: dba: 0x103ea3f: len: 4: Xid:  0x01af.021.00003338: Scn: 2717.-1655999697: Flag: IN USE: FBR: False
Chunk: dba: 0x103ea43: len: 8: Xid:  0x01af.021.00003338: Scn: 2717.-1655999680: Flag: IN USE: FBR: False
Chunk: dba: 0x103ea4b: len: 53: Xid:  0x0000.000.00000000: Scn: 2708.1852084450: Flag: FREE: FBR: False

There are several Persistent Undo Chunks now, with size of 1, 2, 4, 8 as IN USE and 53 FREE.
The LOBs from this insert are in the Chunks with len: 1, 2,4 and partially 8. To reflect the Chunk starting at 0x103ea43 with len: 8 is only partially filled (2 blocks for LOBID: 00000001000099C633AE) another structure is changed:

Hash Bucket - Range: 32k to 64k

Block dump from disk:
buffer tsn: 4 rdba: 0x0103e585 (4/255365)
scn: 0xa9d.9d4b7347 seq: 0x02 flg: 0x04 tail: 0x73473d02
frmt: 0x02 chkval: 0xdefc type: 0x3d=NGLOB: Hash Bucket
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007F880DC72800 to 0x00007F880DC74800
...
  Dump of Hash Bucket Block
  --------------------------------------------------------
Hash Bucket Header Dump
Range: 32k to 64k
Inst:1 Flag:5 Total:0 FSG_COUNT:0 OBJD:454499 Inc:0
Self Descriptive
 fsg_count:0
Head:0x 0x00000000  Tail:0x 0x00000000
 Opcdode:0 Locker Xid: 0x0000.000.00000000
Fsbdba: 0x0    Fbrdba: 0x0
Head Cache Entries
-------------------
-------------------
Tail Cache Entries
-------------------
-------------------
Free Space Chunk Summary
Inst:1 Minc:0 Maxc:0 Count:1 Tot:6 MAXC:1
CFS Chunk List
--------------
Chunk:0 DBA: 0x0103ea45 Len:6 Xid: 0x01af.021.00003338 Ctime:0
Scn: 0x0000.00000000

This CFS Chunk list points to a chunk of 6 blocks (Len: 6) (size: 48k) starting with DBA: 0x103ea45 as free.

Here some meta information about used and unused blocks is stored in NGLOB: Persistent Undo and NGLOB: Hash Bucket blocks. It's also shown LOBs can be split up to fit into the first space available (against filling continuous blocks / least count of extents to avoid fragmentation).

2017-09-04

SecureFile LOB - more inserts

This blog post continues with all the objects and settings from SecureFile LOB - the empty tableSecureFile LOB - the 1st insert and SecureFile LOB - the 1st update

The next insert is a small LOB with 2 bytes again:
insert into berx.TEST_BLOBS
select 2, comments, file_content
from berx.source_blobs
where id=2; 
--2 byte 
The table row points to a new block in the LOB segment:
ROWID   = AABu7gAAEAAA+N/AAA
ROWNUM  = 1
LOBID   = 00000001000099BF67D1
EXTENT# = 0
HOLE?   = n
Superchunk cont? = n
Overallocation  = n
rdba   = 17032590 - 0x  103E58E
File   = 4
Block  = 255374
nblks  = 1
offset = 0
length = 2
---

It's the 4th trans data block:

Block dump from disk:
buffer tsn: 4 rdba: 0x0103e58e (4/255374)
scn: 0xa9c.b1d49a00 seq: 0x02 flg: 0x04 tail: 0x9a000602
frmt: 0x02 chkval: 0x4617 type: 0x06=trans data
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007FDC9B903800 to 0x00007FDC9B905800
7FDC9B903800 0000A206 0103E58E B1D49A00 04020A9C  [................]
...
Block header dump:  0x0103e58e
 Object id on Block? Y
 seg/obj: 0x6ef63  csc: 0xa9c.b1d49a00  itc: 1  flg: E  typ: 5 - LOCAL LOBS
     fsl: 0  fnx: 0xffffffff ver: 0x01

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x01b0.011.000210a9  0x00000000.0000.00  -B--    0  fsc 0x0000.00000000
========
bdba    [0x0103e58e]
kdlich  [0x7fdc9b90384c 56]
  flg0  0x20 [ver=0 typ=data lock=n]
  flg1  0x00
  scn   0x0a9c.b1d49a00
  lid   00000001000099bf67d1
  rid   0x00000000.0000
kdlidh  [0x7fdc9b903864 24]
  flg2  0x00 [ver=0 lid=short-rowid hash=n cmap=n pfill=n]
  flg3  0x00
  pskip 0
  sskip 0
  hash  0000000000000000000000000000000000000000
  hwm   2
  spr   0
  data  [0x7fdc9b903880 52 8060]
41 42 00 6f 00 74 00 68 00 65 00 72 00 5f 00 78 00 6d 00 6c 00 3e 00 3c 00 69

The structure is well known already, lid is equal to LOBID, hwm is 2 bytes and the content is 0x41 0x42 which is A B.

There is no change in any of the Hash Bucket blocks (neither UFS nor CFS).



the 2nd insert is
insert into berx.TEST_BLOBS
select 3, comments, file_content
from berx.source_blobs
where id=3; 
--4 kbyte 

Again only 1 block.

ROWID   = AABu7gAAEAAA+N/AAB
ROWNUM  = 1
LOBID   = 00000001000099C090E3
EXTENT# = 0
HOLE?   = n
Superchunk cont? = n
Overallocation  = n
rdba   = 17032587 - 0x  103E58B
File   = 4
Block  = 255371
nblks  = 1
offset = 0
length = 4038
---

the LOB is now stored in 0x0103e58b - the 1st trans data block. It was used at the 1st insert, but not in use anymore since the 1st update - since then it was on the UFS list.

buffer tsn: 4 rdba: 0x0103e58b (4/255371)
scn: 0xa9c.b1d52068 seq: 0x02 flg: 0x04 tail: 0x20680602
frmt: 0x02 chkval: 0x7711 type: 0x06=trans data
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007FF37EF64800 to 0x00007FF37EF66800
7FF37EF64800 0000A206 0103E58B B1D52068 04020A9C  [........h ......]
7FF37EF64810 00007711 00000005 0006EF63 B1D52068  [.w......c...h ..]
7FF37EF64820 00000A9C 00220001 FFFFFFFF 001D01A9  [......".........]
7FF37EF64830 00001782 00000000 00000000 00004000  [.............@..]
7FF37EF64840 00000000 00000000 00000000 B1D52068  [............h ..]
7FF37EF64850 00200A9C 01000000 C0990000 0000E390  [.. .............]
7FF37EF64860 00000000 00000000 00000000 00000000  [................]
7FF37EF64870 00000000 00000000 00000000 00000FC6  [................]
7FF37EF64880 6C636564 0D657261 2020200A 20202020  [declare..       ]
7FF37EF64890 44495220 20202020 574F5220 0D3B4449  [ RID     ROWID;.]
...
Block header dump:  0x0103e58b
 Object id on Block? Y
 seg/obj: 0x6ef63  csc: 0xa9c.b1d52068  itc: 1  flg: E  typ: 5 - LOCAL LOBS
     fsl: 0  fnx: 0xffffffff ver: 0x01

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x01a9.01d.00001782  0x00000000.0000.00  -B--    0  fsc 0x0000.00000000
========
bdba    [0x0103e58b]
kdlich  [0x7ff37ef6484c 56]
  flg0  0x20 [ver=0 typ=data lock=n]
  flg1  0x00
  scn   0x0a9c.b1d52068
  lid   00000001000099c090e3
  rid   0x00000000.0000
kdlidh  [0x7ff37ef64864 24]
  flg2  0x00 [ver=0 lid=short-rowid hash=n cmap=n pfill=n]
  flg3  0x00
  pskip 0
  sskip 0
  hash  0000000000000000000000000000000000000000
  hwm   4038
  spr   0
  data  [0x7ff37ef64880 52 8060]

Also, nothing fancy here. Everything as expected.

There is another block of interest, the UFS Hash Bucket which UFS List points to this block. It did NOT change and still contains block 0x0103e58b:

Block dump from disk:
buffer tsn: 4 rdba: 0x0103e583 (4/255363)
scn: 0xa9c.916207e5 seq: 0x01 flg: 0x04 tail: 0x07e53d01
frmt: 0x02 chkval: 0xa4e3 type: 0x3d=NGLOB: Hash Bucket
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007FF37EF64800 to 0x00007FF37EF66800
...
  Dump of Hash Bucket Block
  --------------------------------------------------------
Hash Bucket Header Dump
Inst:1 Flag:6 Total:0 FSG_COUNT:0 OBJD:454499 Inc:0
Self Descriptive
 fsg_count:0
Head:0x 0x00000000  Tail:0x 0x00000000
 Opcdode:3 Locker Xid: 0x01b0.019.00020f35
Fsbdba: 0x0    Fbrdba: 0x0
Head Cache Entries
-------------------
-------------------
Tail Cache Entries
-------------------
-------------------
Free Space Chunk Summary
Inst:0 Minc:0 Maxc:0 Count:0 Tot:0 MAXC:1
UFS List
--------------
Deleted - Chunk:0 DBA: 0x0103e58b Len:140681653780481 Xid: 0x01b0.019.00020f35 Ctime:1504343585
Scn: 0x0a9c.9062fe3c
  --------------------------------------------------------


this looks confusing: How can a block which is in use be present in a Free Space list?
My assumption here: as the blocks SCN (0x0a9c.b1d52068) is higher than the UFS entry SCN (0x0a9c.9062fe3c), I'd claim the UFS entry outdated and a cleanup will happen when there is a need to write this Hash Bucket block.

2017-09-02

SecureFile LOB - the 1st update

This blog post continues with all the objects and settings from SecureFile LOB - the empty table and SecureFile LOB - the 1st insert



the statement is quite easy:
update berx.TEST_BLOBS
set (comments, file_content) = 
(select comments, file_content
from berx.source_blobs
where id=4)
;

The new CLOB is about 11.1 kb in size - so it will require more than 1 block.

Fortunately the number of extents did not change.

New information needs to be gathered again:

ALTER SESSION SET TRACEFILE_IDENTIFIER = "UPDATE_PRE_BLOB";  
alter system dump datafile 4 block min 255360 block max 255375;


ALTER SESSION SET TRACEFILE_IDENTIFIER = "UPDATE_PRE_EXT2";  
alter system dump datafile 4 block min 256512 block max 257023;

@LOBMAP.sql (row 1)

System altered.

SQL> ROWID = AABu7gAAEAAA+N7AAA
ROWNUM  = 1
LOBID   = 00000001000099BF531D
EXTENT# = 0
HOLE?   = n
Superchunk cont? = n
Overallocation  = n
rdba   = 17032588 - 0x  103E58C
File   = 4
Block  = 255372
nblks  = 2
offset = 0
length = 11389
---

The LOBID changed. So the lob (for the same row) is in another location now.

In the 2nd extent, as far as I can judge, did not change.

In the 1st extend, some things changed (obviously, somewhere the LOB needs to be stored).

NGLOB: Segment Header stays the same.
all the NGLOB: Hash Bucket blocks stays the same. (that confuses me as I expected at least one of them to change)
Also block 0x0103e58b (trans data) - the one which holds the previous LOB is exactly the same (!)


The new trans data blocks


1st block:
buffer tsn: 4 rdba: 0x0103e58c (4/255372)
scn: 0xa9c.9062fe3c seq: 0x02 flg: 0x04 tail: 0xfe3c0602
frmt: 0x02 chkval: 0xba2b type: 0x06=trans data
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007F98ED985E00 to 0x00007F98ED987E00
7F98ED985E00 0000A206 0103E58C 9062FE3C 04020A9C  [........<.b.....]
7F98ED985E10 0000BA2B 00000005 0006EF63 9062FE3C  [+.......c...<.b.]
7F98ED985E20 00000A9C 00220001 FFFFFFFF 001901B0  [......".........]
7F98ED985E30 00020F33 00000000 00000000 00004000  [3............@..]
7F98ED985E40 00000000 00000000 00000000 9062FE3C  [............<.b.]
7F98ED985E50 00200A9C 01000000 BF990000 00001D53  [.. .........S...]
7F98ED985E60 00000000 00000000 00000000 00000000  [................]
7F98ED985E70 00000000 00000000 00000000 00001F7C  [............|...]
7F98ED985E80 70747468 2F2F3A73 616E6F6A 6E616874  [https://jonathan]
7F98ED985E90 6977656C 6F772E73 72706472 2E737365  [lewis.wordpress.]
7F98ED985EA0 2F6D6F63 35313032 2F31302F 6C2F3132  [com/2015/01/21/l]
7F98ED985EB0 732D626F 65636170 0D0A0D2F 6572630A  [ob-space/....cre]
...
Block header dump:  0x0103e58c
 Object id on Block? Y
 seg/obj: 0x6ef63  csc: 0xa9c.9062fe3c  itc: 1  flg: E  typ: 5 - LOCAL LOBS
     fsl: 0  fnx: 0xffffffff ver: 0x01

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x01b0.019.00020f33  0x00000000.0000.00  -B--    0  fsc 0x0000.00000000
========
bdba    [0x0103e58c]
kdlich  [0x7f98ed985e4c 56]
  flg0  0x20 [ver=0 typ=data lock=n]
  flg1  0x00
  scn   0x0a9c.9062fe3c
  lid   00000001000099bf531d
  rid   0x00000000.0000
kdlidh  [0x7f98ed985e64 24]
  flg2  0x00 [ver=0 lid=short-rowid hash=n cmap=n pfill=n]
  flg3  0x00
  pskip 0
  sskip 0
  hash  0000000000000000000000000000000000000000
  hwm   8060
  spr   0
  data  [0x7f98ed985e80 52 8060]
68 74 74 70 73 3a 2f 2f 6a 6f 6e 61 74 68 61 6e 6c 65 77 69 73 2e 77 6f 72 64
70 72 65 73 73 2e 63 6f 6d 2f 32 30 31 35 2f 30 31 2f 32 31 2f 6c 6f 62 2d 73
70 61 63 65 2f 0d 0a 0d 0a 63 72 65 61 74 65 20 74 61 62 6c 65 20 74 65 73 74
...

It is the rdba as described in the lob extent map above and references the lid == LOBID. Also the content is correct (this file is an early copy of my scratchpad to this topic). The hwm is 8060 which is smaller as the length of the LOB (11389).
Also nblks is 2, the next block is of some interest as well.

2nd block:

Block dump from disk:
buffer tsn: 4 rdba: 0x0103e58d (4/255373)
scn: 0xa9c.9062fe3c seq: 0x02 flg: 0x04 tail: 0xfe3c0602
frmt: 0x02 chkval: 0xb95a type: 0x06=trans data
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007F98ED985E00 to 0x00007F98ED987E00
...
Block header dump:  0x0103e58d
 Object id on Block? Y
 seg/obj: 0x6ef63  csc: 0xa9c.9062fe3c  itc: 1  flg: E  typ: 5 - LOCAL LOBS
     fsl: 0  fnx: 0xffffffff ver: 0x01

 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x01b0.019.00020f33  0x00000000.0000.00  -B--    0  fsc 0x0000.00000000
========
bdba    [0x0103e58d]
kdlich  [0x7f98ed985e4c 56]
  flg0  0x20 [ver=0 typ=data lock=n]
  flg1  0x00
  scn   0x0a9c.9062fe3c
  lid   00000001000099bf531d
  rid   0x00000000.0000
kdlidh  [0x7f98ed985e64 24]
  flg2  0x00 [ver=0 lid=short-rowid hash=n cmap=n pfill=n]
  flg3  0x00
  pskip 0
  sskip 0
  hash  0000000000000000000000000000000000000000
  hwm   3329
  spr   0
  data  [0x7f98ed985e80 52 8060]

This block contains the remaining part of the LOB. hwm shows it contains the remaining bytes.


The new LOB is present in the LOB segment, the old one is still present - exactly as I'd expect as UNDO is handled as copy on write in LOBs. It's only confusing to see no indication (visible to me) that block 0x0103e58b is old and not used anymore.



After some time, (but no activity on the DB) block dumps are created again:

ALTER SESSION SET TRACEFILE_IDENTIFIER = "UPDATE_COM_LONGTIME_BLOB";  
alter system dump datafile 4 block min 255360 block max 255375;

ALTER SESSION SET TRACEFILE_IDENTIFIER = "UPDATE_COM_LONGTIME_EXT2";  
alter system dump datafile 4 block min 256512 block max 257023;

Now there is an interesting change:

2nd NGLOB: Hash Bucket

(part of UFS)
Block dump from disk:
buffer tsn: 4 rdba: 0x0103e583 (4/255363)
scn: 0xa9c.916207e5 seq: 0x01 flg: 0x04 tail: 0x07e53d01
frmt: 0x02 chkval: 0xa4e3 type: 0x3d=NGLOB: Hash Bucket
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007F9AFDEAE800 to 0x00007F9AFDEB0800
...
  Dump of Hash Bucket Block
  --------------------------------------------------------
Hash Bucket Header Dump
Inst:1 Flag:6 Total:0 FSG_COUNT:0 OBJD:454499 Inc:0
Self Descriptive
 fsg_count:0
Head:0x 0x00000000  Tail:0x 0x00000000
 Opcdode:3 Locker Xid: 0x01b0.019.00020f35
Fsbdba: 0x0    Fbrdba: 0x0
Head Cache Entries
-------------------
-------------------
Tail Cache Entries
-------------------
-------------------
Free Space Chunk Summary
Inst:0 Minc:0 Maxc:0 Count:0 Tot:0 MAXC:1
UFS List
--------------
Deleted - Chunk:0 DBA: 0x0103e58b Len:140299401691137 Xid: 0x01b0.019.00020f35 Ctime:1504343585
Scn: 0x0a9c.9062fe3c
  --------------------------------------------------------

No clue why this block changed in between.
Ctime: is epoc for GMT: Saturday, September 2, 2017 9:13:05 AM (when the update was done) and Scn: is the exact SCN when the new LOB was written.

Now it makes some sense, but it's unclear what changed the block between the 2 dumps.


2017-09-01

SecureFile LOB - move online in 12.2

Today we had a "new features in 12.2" workshop. Thank you Mathias Zarick for this great event.
One of the new features was Online Table Move. But the doc was quite unspecific if this also includes LOBs:
Nonpartitioned tables can be moved as an online operation without blocking any concurrent DML operations. A table move operation now also supports automatic index maintenance as part of the move.
Data maintenance on nonpartitioned tables does not require any maintenance window since it does not impact any DML or query operation.
So it's worth a test-case in my 12.2 sandbox:

There are 2 tables (test_blobs and test_blobs2) of this structure:
create table test_blobs (
        id              number(5),
  comments        varchar2(80),
        file_content    blob
) 
SEGMENT CREATION IMMEDIATE 
NOCOMPRESS 
NOPARALLEL 
TABLESPACE  USERS
lob (file_content) store as SECUREFILE(
        disable storage in row
        chunk 16K
        tablespace users
)
;

test_blobs2 has 2 rows (id 1 & 2) with different blobs.

Session 1:

20:58:57 SQL> update test_blobs set file_content=(select file_content from test_blobs2 where id=1);                                                                                                                     

1 row updated.
         

Session 2:

20:58:58 SQL>                                                                                                                                                                                                           
                                                                                                                                                                                                                        
ALTER TABLE test_blobs MOVE LOB(file_content) 
20:59:09 SQL> 20:59:09   2    STORE AS ( TABLESPACE users2) online;                                                                                                                                                     
                                                                                                                                                                                                                        
               

Session 1:

20:59:10 SQL> commit;                                                                                                                                                                                                   

Commit complete.   


Session 2:

Table altered.
                                                                                                                                                
20:59:18 SQL> 

Here the ALTER TABLE ... MOVE LOB ... STORA AS (TABLESPACE ...) ONLINE works.
That's very good news!

The Segment is really there:
21:02:33 SQL> select segment_name, tablespace_name from dba_segments where owner='BERX' and segment_name in                                                                                                             
21:02:34   2  (select segment_name from dba_lobs where table_name='TEST_BLOBS' and column_name='FILE_CONTENT');                                                                                                         

SEGMENT_NAME                             TABLESPACE_NAME
---------------------------------------- ------------------------------
SYS_LOB0000058821C00003$$                USERS2

And the move just waited until the row lock completed.

I really would like to have this feature in 12.1, but it's good to know it will come to my DBs some-when in the future.