X-Git-Url: http://git.jankratochvil.net/?p=captive.git;a=blobdiff_plain;f=src%2FTraceFS%2Fchecktrace.pl;h=61c63e89abaef4f84d7ba0767dbf82fead92ff8d;hp=688b65e18a28e61f5dc43d058d2bf388ad11c134;hb=HEAD;hpb=72446ee0bb51e594f4743cc663903ef7173b1e45

diff --git a/src/TraceFS/checktrace.pl b/src/TraceFS/checktrace.pl
index 688b65e..61c63e8 100755
--- a/src/TraceFS/checktrace.pl
+++ b/src/TraceFS/checktrace.pl
@@ -31,7 +31,7 @@ my $ntfs_blocksize=0x200;
 # $Object->{"by"}="CcSomeFunction";
 # $Object->{"line_enter"}=123;
 # $Object->{"line_leave"}=124;
-# $Object->{"process_thread"}="0x12345678/0x12345678";
+# $Object->{"ProcessThread"}="0x12345678/0x12345678";
 # $Object->{"data"}[dataline]{"FileObject"}="0x12345678";
 # $Object->{"data"}[dataline]{"FileName"}="\filename" or undef() if NULL;
 # $Object->{"data"}[dataline]{"Flags"}="0x40100";
@@ -43,23 +43,42 @@ my $ntfs_blocksize=0x200;
 # $SectionObjectPointer{$SectionObjectPointer}{"SharedCacheMap"}="0x12345678";
 # $SharedCacheMap{$SharedCacheMap}{"SharedCacheMap"}="0x12345678";
 # $SharedCacheMap{$SharedCacheMap}{"SectionObjectPointer"}="0x12345678";
-# $SharedCacheMap{$SharedCacheMap}{"Allocation"}="0x12345";
+# $SharedCacheMap{$SharedCacheMap}{"AllocationSize"}="0x12345";
 # $SharedCacheMap{$SharedCacheMap}{"FileSize"}="0x12345";
 # $SharedCacheMap{$SharedCacheMap}{"ref_count"}=1;
 # $SharedCacheMap{$SharedCacheMap}{"map"}="0x12345678" (Bcb);
-# $SharedCacheMap{$SharedCacheMap}{"pin"}{"0x1000"}="0x12345678" (Bcb);
+# $SharedCacheMap{$SharedCacheMap}{"pin"}{"0x1000"}="0x12345678" (Bcb) if !Bcb->{"OwnerPointer"};
 # $SharedCacheMap{$SharedCacheMap}{"PinAccess"}=0 or 1;
+# $SharedCacheMap{$SharedCacheMap}{"LogHandle"}="0x12345678" optional;
+# $SharedCacheMap{$SharedCacheMap}{"AcquireForLazyWrite"}=0;	# count
+# $SharedCacheMap{$SharedCacheMap}{"in_memory"}{"0x4000"}=1;	# mapped page?
+# $SharedCacheMap{$SharedCacheMap}{"Buffer"}="0x12345678";
+# $LogHandle{$LogHandle}{"LogHandle"}="0x12345678";
 # $Bcb{$Bcb}{"Bcb"}="0x12345678";
 # $Bcb{$Bcb}{"SharedCacheMap"}="0x12345678";
 # $Bcb{$Bcb}{"type"}="pin" or "map";
 # $Bcb{$Bcb}{"ref_count"}=1;
 # $Bcb{$Bcb}{"FileOffset"}="0x1000" if {"type"} eq "pin";
 # $Bcb{$Bcb}{"Buffer"}="0x12345678";	# PAGE_SIZE-aligned for "pin", FileOffset_0-aligned for "map"
+# $Bcb{$Bcb}{"OwnerPointer"}="0x12345678" optional;
+# $Bcb{$Bcb}{"Lsn"}="0x12345678" optional;
+# $Bcb{$Bcb}{"dirty"}=1 optional;
+# $MdlChain{$MdlChain}{"MdlChain"}="0x12345678";
+# $MdlChain{$MdlChain}{"FileObject"}="0x12345678";
+# $MdlChain{$MdlChain}{"FileOffset"}="0x5000";
+# $MdlChain{$MdlChain}{"Length"}="0x9000";
 
 my %FileObject;
+my %LogHandle;
 my %SectionObjectPointer;
 my %SharedCacheMap;
 my %Bcb;
+my %MdlChain;
+my %LastLeave;	# $ProcessThread=>[$Object,$Object,...]
+my $LastLeave;	# ref copy of the last item for the current $ProcessThread
+my $ProcessThread;
+my %EnterLeave;
+my $EnterLeave;	# ref copy of the list for the current $ProcessThread
 
 END {
 	print Data::Dumper->Dump([\%FileObject,\%SectionObjectPointer,\%SharedCacheMap,\%Bcb],
@@ -87,6 +106,14 @@ my($FileObject)=@_;
 	return $FObject;
 }
 
+sub delete_FObject($)
+{
+my($FObject)=@_;
+
+	my $FileObject=$FObject->{"FileObject"};
+	delete $FileObject{$FileObject};
+}
+
 sub SObject($)
 {
 my($SectionObjectPointer)=@_;
@@ -119,6 +146,13 @@ my($CObject)=@_;
 	my $SharedCacheMap=$CObject->{"SharedCacheMap"};
 	do { warn "Trailing map $_ of SharedCacheMap $SharedCacheMap during its deletion" if $_; } for ($CObject->{"map"});
 	do { warn "Trailing pin $_ of SharedCacheMap $SharedCacheMap during its deletion" if $_; } for (values(%{$CObject->{"pin"}}));
+	if (my $LogHandle=$CObject->{"LogHandle"}) {
+		do { warn "INTERNAL: Missing LogHandle $LogHandle for SharedCacheMap $SharedCacheMap"; return; }
+			if !(my $LObject=$LogHandle{$LogHandle});
+		# Do not delete $LogHandle as it may be used by many SharedCacheMap-s
+		}
+	warn "ref_count=".$CObject->{"ref_count"}." of SharedCacheMap $SharedCacheMap during its deletion"
+			if $CObject->{"ref_count"};
 	delete $SharedCacheMap{$SharedCacheMap};
 }
 
@@ -181,7 +215,12 @@ my($data)=@_;
 		}
 	return if !$FileObject{$data->{"FileObject"}};
 	return if !(my $FObject=FObject $data->{"FileObject"});
-	return if !(my $SObject=SObject $FObject->{"SectionObjectPointer"});
+	$SectionObjectPointer=$FObject->{"SectionObjectPointer"};
+	return if !(my $SObject=SObject $SectionObjectPointer);
+	warn "FileObject ".$FObject->{"FileObject"}
+					." expected SectionObjectPointer $SectionObjectPointer"
+					." but found SectionObjectPointer ".$data->{"SectionObjectPointer"}
+			if $SectionObjectPointer ne $data->{"SectionObjectPointer"};
 	my $SharedCacheMap=$SObject->{"SharedCacheMap"};
 	warn "FileObject ".$FObject->{"FileObject"}." SectionObjectPointer ".$SObject->{"SectionObjectPointer"}
 					." expected SharedCacheMap $SharedCacheMap"
@@ -214,8 +253,11 @@ sub CcInitializeCacheMap_leave()
 	if (!SharedCacheMap_valid $Object->{"data"}[0]{"SharedCacheMap"} && $old) {
 		# SharedCacheMap got deleted in the meantime
 		delete_CObject CObject $SharedCacheMap;
-		my $SObject=SObject $Object->{"data"}[0]{"SectionObjectPointer"};
-		$SObject->{"SharedCacheMap"}=tohex(0);
+		# Either it got deleted of some foreign SectionObjectPointer
+		# or of the current one:
+		if (my $SObject=$SectionObjectPointer{$Object->{"data"}[0]{"SectionObjectPointer"}}) {
+			$SObject->{"SharedCacheMap"}=tohex(0);
+			}
 		$old=undef();
 		}
 	if (!$old != !SharedCacheMap_valid $Object->{"data"}[0]{"SharedCacheMap"}) {
@@ -340,6 +382,11 @@ my($FileObject,$AllocationSize,$FileSize,$ValidDataLength)=@_;
 		do { warn "Existing pin $_ of FileObject $FileObject SharedCacheMap $SharedCacheMap during CcSetAllocationSizes(),"
 						." AllocationSize=".$CObject->{"AllocationSize"} if $_; }
 				for (values(%{$CObject->{"pin"}}));
+		# Do not: delete $CObject->{"in_memory"};
+		# as its keep is required by W32. Squeeze it instead:
+		$CObject->{"in_memory"}={ map({
+				(eval($_)<$AllocationSize ? ($_=>1) : ());
+				} keys(%{$CObject->{"in_memory"}})) };
 		}
 	# $ValidDataLength can be > $CObject->{"FileSize"};
 	warn "ValidDataLength ".tohex($ValidDataLength)." > FileSize ".tohex($FileSize)
@@ -351,6 +398,7 @@ my($FileObject,$AllocationSize,$FileSize,$ValidDataLength)=@_;
 			if $FileSize>$AllocationSize;
 	$CObject->{"FileSize"}=tohex($FileSize);
 	$CObject->{"AllocationSize"}=tohex($AllocationSize);
+	delete $CObject->{"Buffer"} if !eval $AllocationSize;
 }
 
 sub IRP_MJ_CREATE_leave()
@@ -384,11 +432,84 @@ sub BObject($)
 {
 my($Bcb)=@_;
 
+	cluck if !defined $Bcb;
 	my $BObject=$Bcb{$Bcb};
-	warn "Non-existent Bcb $Bcb" if !$BObject;
+	if (!$BObject) {
+		my($package,$filename,$line,$subroutine)=caller 0;
+		warn "Non-existent Bcb $Bcb by line $line"
+		}
 	return $BObject;
 }
 
+sub delete_BObject($)
+{
+my($BObject)=@_;
+
+	my $Bcb=$BObject->{"Bcb"};
+#	warn "XXX delete_BObject 0x811799B8 line $. BObject=".Dumper $BObject if $Bcb eq "0x811799B8";
+	warn "Deleting ref_count=".$BObject->{"ref_count"}." Bcb $Bcb" if $BObject->{"ref_count"};
+	# Do not: warn "Deleting dirty Bcb $Bcb" if $BObject->{"dirty"};
+	# as it is valid to allow sanity check below.
+	warn "Deleting dirty Bcb $Bcb" if $BObject->{"dirty"} && $BObject->{"ref_count"};
+	return if !(my $CObject=CObject $BObject->{"SharedCacheMap"});
+	if ($BObject->{"type"} eq "map") {
+		for my $pin (values(%{$CObject->{"pin"}})) {
+			next if !defined $pin;
+			warn "unpin map but CcPinMappedData pin $pin still exists"
+					if $Bcb{$pin}->{"by"} eq "CcPinMappedData";
+			}
+		}
+	else {
+		warn "unpin of pin Bcb $Bcb of SharedCacheMap ".$CObject->{"SharedCacheMap"}
+						." although FileOffset ".$BObject->{"FileOffset"}." not in_memory"
+				if !($CObject->{"in_memory"}{$BObject->{"FileOffset"}});
+		# Do not: delete $CObject->{"in_memory"}{$BObject->{"FileOffset"}};
+		# as Cache Manager is not forced to drop it.
+#		warn "UNMARK: SharedCacheMap ".$CObject->{"SharedCacheMap"}." FileOffset ".$BObject->{"FileOffset"};
+		}
+	for my $ref ($BObject->{"type"} eq "map" ? \$CObject->{"map"} : \$CObject->{"pin"}{$BObject->{"FileOffset"}}) {
+		warn "Final unpin but ".$BObject->{"type"}." Bcb $Bcb not registered"
+						." in SharedCacheMap ".$CObject->{"SharedCacheMap"}." ref ".($$ref || "<undef>")
+				if !defined($BObject->{"OwnerPointer"}) && !($$ref && $$ref eq $Bcb)
+						&& !($BObject->{"ref_count"}==0 && $BObject->{"dirty"});
+		if ($$ref && $$ref eq $Bcb) {
+			$$ref=undef();
+			# Do not: delete $CObject->{"pin"}{$BObject->{"FileOffset"}} if $BObject->{"type"} eq "pin";
+			# as it would destroy $$ref slot in &Bcb_checkref '($$ref && $Bcb ne $$ref)' codepath.
+			}
+		}
+	delete $Bcb{$Bcb};
+#	warn "XXX delete_BObject 0x811799B8 line $. CObject=".Dumper $CObject if $Bcb eq "0x811799B8";
+	CObject_Buffer_check($CObject);
+}
+
+sub MObject($)
+{
+my($MdlChain)=@_;
+
+	cluck if !defined $MdlChain;
+	my $MObject=$MdlChain{$MdlChain};
+	warn "Non-existent MdlChain $MdlChain" if !$MObject;
+	return $MObject;
+}
+
+sub CObject_Buffer_check($)
+{
+my($CObject)=@_;
+
+	my $any;
+	for my $BObject ($CObject->{"map"},values(%{$CObject->{"pin"}})) {
+		# There may exist OwnerPointer-ed or dirty&unreffed standalone Bcbs bound to this SharedCacheMap
+		# but these are not important for Buffer reset.
+		next if !$BObject;
+		$any=1;
+		last;
+		}
+	if (!$any) {
+		delete $CObject->{"Buffer"};
+		}
+}
+
 sub Bcb_conflict($;@)
 {
 my($CObject,@Bcb_list)=@_;
@@ -402,17 +523,29 @@ my($CObject,@Bcb_list)=@_;
 	my %reversed;
 	my $BufferBase;	# relativized to FileOffset 0
 	my $BufferBase_val;
+	if ($CObject->{"Buffer"}) {
+		$BufferBase=eval $CObject->{"Buffer"};
+		$BufferBase_val="SharedCacheMap Buffer";
+		}
 	while (my($key,$val)=each(%check)) {
 		next if !defined $val;
 		warn "Conflicting Bcb $val of keys $key and ".$reversed{$val}." of SharedCacheMap ".$CObject->{"SharedCacheMap"}
 				if $reversed{$val};
 		# Buffer base should match even between 'map's and 'pin's
 		# as the data are always mapped only once.
-		if (my $BObject=BObject $val) {
+		my $BObject=$Bcb{$val};
+		warn "Non-existent key=$key Bcb $val"
+#						." XXX line $. CObject=".Dumper $CObject
+				if !$BObject;
+		if ($BObject) {
 			my $Buffer=eval $BObject->{"Buffer"};
 			$Buffer-=eval($BObject->{"FileOffset"}) if exists $BObject->{"FileOffset"};
+			warn "INTERNAL: Non page aligned Buffer ".tohex($Buffer)." of Bcb $val"
+					if $Buffer & 0xFFF;
 			warn "Non-matching Bcb ".$BObject->{"type"}." $val Buffer base ".tohex($Buffer)
-							." with Bcb ".$Bcb{$BufferBase_val}->{"type"}." $BufferBase_val BufferBase ".tohex($BufferBase)
+							." with".($BufferBase_val=~/^SharedCacheMap / ? "" : " Bcb ".$Bcb{$BufferBase_val}->{"type"})
+							." $BufferBase_val BufferBase ".tohex($BufferBase)."; SharedCacheMap=".$CObject->{"SharedCacheMap"}
+#							." XXX line $. ".Dumper($CObject,\%Bcb)
 					if defined($BufferBase) && $Buffer!=$BufferBase;
 			$BufferBase=$Buffer;
 			$BufferBase_val=$val;
@@ -429,21 +562,27 @@ my($BObject,$ref)=@_;
 	return if !(my $CObject=CObject $BObject->{"SharedCacheMap"});
 	my $type=$BObject->{"type"};
 	my $Bcb=$BObject->{"Bcb"};
-	if ($$ref) {
+	if ($$ref && $Bcb ne $$ref) {
 		my $BObject2=$Bcb{$$ref};
-		warn "new $type Bcb $Bcb != old $type Bcb $$ref"
-				if $Bcb ne $$ref;
-		warn "new $type $Bcb type ".$BObject->{"type"}." != old $type $$ref type ".$BObject2->{"type"}
+		warn "new $type Bcb $Bcb != old ".$BObject2->{"type"}." Bcb $$ref";
+		delete_BObject $BObject2;
+		}
+	if ($Bcb{$Bcb}) {
+		my $BObject2=$Bcb{$Bcb};
+		warn "new $type $Bcb type ".$BObject->{"type"}." != old type $type $Bcb type ".$BObject2->{"type"}
 				if $BObject->{"type"} ne $BObject2->{"type"};
-		warn "new $type $Bcb Buffer ".$BObject->{"Buffer"}." != old $type $$ref Buffer ".$BObject2->{"Buffer"}
+		warn "new $type $Bcb Buffer ".($BObject->{"Buffer"} || "<undef>")
+						." != old $type $Bcb Buffer ".($BObject2->{"Buffer"} || "<undef>")
+#						." XXX line $. ".Dumper($BObject,$BObject2)
 				if $BObject->{"Buffer"} ne $BObject2->{"Buffer"};
 		}
-	if ($$ref && $$ref eq $Bcb) {
-		$BObject->{"ref_count"}+=$Bcb{$$ref}->{"ref_count"};
-		$$ref=undef();
+	if ($Bcb{$Bcb}) {
+		warn "Equal Bcb?" if $Bcb{$Bcb} eq $BObject;
+		$Bcb{$Bcb}->{"ref_count"}+=$BObject->{"ref_count"};
+		$BObject=$Bcb{$Bcb};
 		}
 	$Bcb{$Bcb}=$BObject;	# &Bcb_conflict needs this reference
-	Bcb_conflict $CObject,$Bcb;
+	Bcb_conflict $CObject,($$ref && $$ref eq $Bcb ? () : ($Bcb));
 	$$ref=$Bcb;
 }
 
@@ -483,6 +622,8 @@ my($Bcb,$Buffer)=@_;
 		$Object->{"Buffer"}=tohex(eval($Buffer)-(eval($Object->{"FileOffset"}) || 0));
 		}
 	delete $Object->{"FileOffset"};
+	$CObject->{"Buffer"}=$Object->{"Buffer"} if !$CObject->{"Buffer"};
+	warn "Unknown Buffer during map_new_leave" if !$Object->{"Buffer"};
 
 	my $ref=\$CObject->{"map"};
 	# There may exist some pin bcbs even if we are creating the new map bcb.
@@ -531,9 +672,17 @@ my($Bcb,$Buffer)=@_;
 	$Object->{"FileOffset"}=tohex(eval($Object->{"FileOffset"})-$shift);
 	$Object->{"Buffer"}=tohex(eval($Buffer)-$shift);
 
+	my $Buffer_base=tohex(eval($Object->{"Buffer"})-eval($Object->{"FileOffset"}));
+	$CObject->{"Buffer"}=$Buffer_base if !$CObject->{"Buffer"};
+
+	warn "pin_new_leave() while FileOffset ".$Object->{"FileOffset"}." not in_memory"
+					." of SharedCacheMap ".$CObject->{"SharedCacheMap"}
+			if !$CObject->{"in_memory"}{$Object->{"FileOffset"}};
+
 	my $ref=\$CObject->{"pin"}{$Object->{"FileOffset"}};
 	# There may not exist map bcb even if we are creating the new pin bcb.
 	Bcb_checkref $Object,$ref;
+#	warn "XXX pin_new_leave line $. BObject=".Dumper $Object if $Bcb eq "0x811799B8";
 }
 
 sub CcPinRead($$$)
@@ -554,6 +703,12 @@ sub CcPreparePinWrite($$$)
 {
 my($FileObject,$FileOffset,$Length)=@_;
 
+	return if !(my $CObject=CObject_from_FileObject $FileObject);
+	# Full pages do not need to be read:
+	if (!($FileOffset&0xFFF)) {
+		$CObject->{"in_memory"}{tohex $FileOffset}=1;
+		}
+
 	pin_new $FileObject,$FileOffset,$Length;
 }
 
@@ -562,6 +717,8 @@ sub CcPreparePinWrite_leave($$)
 my($Bcb,$Buffer)=@_;
 
 	pin_new_leave $Bcb,$Buffer;
+	my $BObject=BObject $Bcb;
+	$BObject->{"dirty"}=1;
 }
 
 sub CcPinMappedData($$$)
@@ -576,29 +733,18 @@ sub CcPinMappedData_leave($)
 my($Bcb)=@_;
 
 	return if !(my $CObject=CObject $Object->{"SharedCacheMap"});
-	do { warn "CcPinMappedData() with Bcb $Bcb on non-CcMapData()ed SharedCacheMap ".$CObject->{"SharedCacheMap"}; return; }
-			if !(my $mapBcb=$CObject->{"map"});
-	return if !(my $BmapObject=BObject $mapBcb);
-	my $Buffer=tohex(eval($BmapObject->{"Buffer"})+eval($Object->{"FileOffset"}));
-
-	my $Bcb2=$CObject->{"pin"}{tohex(eval($Object->{"FileOffset"})&~0xFFF)};
-	my $BObject2=BObject $Bcb2 if $Bcb2;
-	if ($BObject2 && $BObject2->{"CcPinMappedData_double"}
-			&& eval($BObject2->{"CcPinMappedData_double"})==eval($Object->{"FileOffset"})) {	# unaligned yet
-		my $BmapBuffer=eval($BmapObject->{"Buffer"})+(eval($Object->{"FileOffset"})&~0xFFF);
-		warn "CcPinMappedData-double cludge non-matching new Bcb $Bcb != old Bcb ".$BObject2->{"Bcb"}
-				if $Bcb ne $BObject2->{"Bcb"};
-		warn "CcPinMappedData-double cludge non-matching Buffer new Bcb $Bcb Buffer $BmapBuffer"
-						." != old Bcb ".$BObject2->{"Bcb"}." Buffer ".$BObject2->{"Buffer"}
-				if eval($BmapBuffer)!=eval($BObject2->{"Buffer"});
-		return;
-		}
+	# Do not: do { warn "CcPinMappedData() with Bcb $Bcb on non-CcMapData()ed SharedCacheMap ".$CObject->{"SharedCacheMap"}; return; }
+	#             if !$CObject->{"map"};
+	# as the only requirement of CcPinMappedData() is to have all the pages already 'in_memory'.
+	my $Buffer=$CObject->{"Buffer"};
+	warn "SharedCacheMap ".$CObject->{"SharedCacheMap"}." Buffer not known during CcPinMappedData()"
+			if !$Buffer;
+	$Buffer=tohex(eval($Buffer)+eval($Object->{"FileOffset"})) if $Buffer;
 
-	# It appears as this cludge is not needed:
-#	$Object->{"CcPinMappedData_double"}=$Object->{"FileOffset"};	# unaligned yet
+#	my $Bcb2=$CObject->{"pin"}{tohex(eval($Object->{"FileOffset"})&~0xFFF)};
+#	my $BObject2=BObject $Bcb2 if $Bcb2;
 
 	pin_new_leave $Bcb,$Buffer;
-#	print STDERR "$.:".Dumper($Object);
 }
 
 sub CcSetDirtyPinnedData($$)
@@ -606,7 +752,289 @@ sub CcSetDirtyPinnedData($$)
 my($Bcb,$Lsn)=@_;
 
 	return if !(my $BObject=BObject $Bcb);
-	delete $BObject->{"CcPinMappedData_double"};
+	# Do not: warn "Lsn already set for Bcb $Bcb as ".$BObject->{"Lsn"}." while current Lsn=$Lsn" if $BObject->{"Lsn"};
+	# as it is permitted.
+	warn "Lsn goes backward for Bcb $Bcb old Lsn ".$BObject->{"Lsn"}." to a new Lsn=$Lsn"
+			if $BObject->{"Lsn"} && eval($BObject->{"Lsn"})>eval($Lsn);
+	$BObject->{"Lsn"}=$Lsn if $Lsn ne "0x".("F"x8);
+	$BObject->{"dirty"}=1;
+	return if !(my $CObject=CObject $BObject->{"SharedCacheMap"});
+}
+
+sub FlushToLsnRoutine($$)
+{
+my($LogHandle,$Lsn)=@_;
+
+	$Object->{"LogHandle"}=$LogHandle;
+	$Object->{"Lsn"}=$Lsn;
+
+	my $obj=${$EnterLeave}[$#$EnterLeave-1];
+	warn "FLUSH" if $obj->{"by"} eq "CcFlushCache";
+}
+
+my $LogHandle_static;
+sub CcSetLogHandleForFile($$$)
+{
+my($FileObject,$LogHandle,$FlushToLsnRoutine)=@_;
+
+	return if !(my $CObject=CObject_from_FileObject $FileObject);
+	warn "LogHandle ".$CObject->{"LogHandle"}." already exists for SharedCacheMap ".$CObject->{"SharedCacheMap"}
+			if $CObject->{"LogHandle"};
+	return if !eval $LogHandle;	# $LogHandle may be "0x0"
+	# ntfs.sys uses single LogHandle for its whole session:
+	warn "Non-unique LogHandle $LogHandle while last LogHandle was $LogHandle_static"
+			if $LogHandle_static && $LogHandle ne $LogHandle_static;
+	$CObject->{"LogHandle"}=$LogHandle;
+	if (!$LogHandle{$LogHandle}) {
+		$LogHandle{$LogHandle}={
+				"LogHandle"=>$LogHandle,
+				};
+		}
+}
+
+sub IRP_MJ_WRITE_leave_page($$)
+{
+my($ByteOffset,$Lsn_check)=@_;
+
+	my $SharedCacheMap=$Object->{"data"}[0]{"SharedCacheMap"};
+	return if !(my $CObject=CObject $SharedCacheMap);
+	my $FlushToLsnRoutine=$LastLeave if $LastLeave->{"by"} eq "FlushToLsnRoutine";
+	# Do not: my $Bcb=$CObject->{"pin"}{$ByteOffset};
+	# as Bcbs with $BObject->{"OwnerPointer"} are no longer stored in $CObject->{"pin"}.
+	my @Bcbs;
+	for my $Bcb (keys(%Bcb)) {
+		my $BObject=BObject $Bcb;
+		if (1
+				&& $BObject->{"type"} eq "pin"
+				&& $BObject->{"SharedCacheMap"} eq $SharedCacheMap
+				&& $BObject->{"FileOffset"} eq $ByteOffset) {
+			push @Bcbs,$Bcb;
+			}
+		}
+	if (!@Bcbs) {
+		do {
+				warn "Non-Bcb IRP_MJ_WRITE ByteOffset=$ByteOffset as non-toplevel function"
+						." (".join(",",map({ $_->{"line_enter"}.":".$_->{"by"}; } @$EnterLeave)).")";
+#				warn Dumper $CObject;
+				# Direct IRP_MJ_WRITE can be from callbacked 'FlushToLsnRoutine'.
+				# It can occur even from other callbacks ('DirtyPageRoutine' etc.)
+				# but it was not needed here yet.
+				} if @$EnterLeave && !(${$EnterLeave}[$#$EnterLeave]->{"by"}=~/^(?:FlushToLsnRoutine\b|IRP_MJ_)/);
+		warn "Non-Bcb IRP_MJ_WRITE ByteOffset=$ByteOffset but FlushToLsnRoutine was preceding"
+				if $FlushToLsnRoutine;
+		return;
+		}
+	$CObject->{"in_memory"}{$ByteOffset}=1;
+	warn "Ambiguous matching Bcbs ".join(",",@Bcbs)
+					." to SharedCacheMap $SharedCacheMap WRITE ByteOffset $ByteOffset"
+			if @Bcbs>=2;
+	my $Bcb=$Bcbs[0];
+	return if !(my $BObject=BObject $Bcb);
+	warn "IRP_MJ_WRITE on non-dirty Bcb $Bcb" if !$BObject->{"dirty"};
+	if ($FlushToLsnRoutine) {
+		push @$Lsn_check,{
+				"Bcb"=>$Bcb,
+				"Bcb_Lsn",$BObject->{"Lsn"},
+				} if $Lsn_check;
+		}
+	else {
+		warn "Missing preceding FlushToLsnRoutine during IRP_MJ_WRITE of Bcb $Bcb with Lsn ".$BObject->{"Lsn"}
+				if $BObject->{"Lsn"};
+		}
+	warn "IRP_MJ_WRITE with FlushToLsnRoutine although not in AcquireForLazyWrite or CcFlushCache"
+			if $FlushToLsnRoutine && !((1==@$EnterLeave && ${$EnterLeave}[0]->{"by"} eq "CcFlushCache")
+			                        || (2==@$EnterLeave && ${$EnterLeave}[0]->{"by"}=~/^IRP_MJ_/
+			                                            && ${$EnterLeave}[1]->{"by"} eq "CcFlushCache"))
+			                      && !($CObject->{"AcquireForLazyWrite"}>=1);
+	warn "IRP_MJ_WRITE not the toplevel function"
+						." (".join(",",map({ $_->{"line_enter"}.":".$_->{"by"}; } @$EnterLeave)).")"
+			if !(0==@$EnterLeave
+			 || (1==@$EnterLeave && ${$EnterLeave}[0]->{"by"} eq "CcFlushCache")
+			 || (2==@$EnterLeave && ${$EnterLeave}[0]->{"by"}=~/^IRP_MJ_/
+			                     && ${$EnterLeave}[1]->{"by"} eq "CcFlushCache"));
+	my $CcFlushCache=${$EnterLeave}[$#$EnterLeave];
+	if ($CcFlushCache && $CcFlushCache->{"by"} eq "CcFlushCache") {
+		$CcFlushCache->{"CcFlushCached"}++;
+		if ($CcFlushCache->{"FileOffset"} ne "0x".("F"x8) || $CcFlushCache->{"Length"} ne "0x0") {
+			warn "IRP_MJ_WRITE outside of range of active CcFlushCache()"
+					if eval($ByteOffset)< eval($CcFlushCache->{"FileOffset"})
+					|| eval($ByteOffset)>=eval($CcFlushCache->{"FileOffset"})+eval($CcFlushCache->{"Length"});
+			}
+		}
+	# Keep $BObject->{"dirty"} there for &delete_BObject sanity checks.
+	delete_BObject $BObject if $BObject->{"dirty"} && !$BObject->{"ref_count"};
+}
+
+sub IRP_MJ_WRITE_leave()
+{
+	return if !(my $CObject=CObject $Object->{"data"}[0]{"SharedCacheMap"});
+	# toplevel IRP_MJ_WRITE has no requirements
+	return if 0==@$EnterLeave
+			# We do not need any outer function, just 'AcquireForLazyWrite' is enough
+			# for flushing Cache Manager buffers by some its LazyWriter task.
+			&& !$CObject->{"AcquireForLazyWrite"};
+	do { warn "Length $_ not divisible by 0x1000" if eval($_)%0x1000; } for ($Object->{"WRITE"}{"Length"});
+	my @Lsn_check;
+	for my $reloffs (0..(eval($Object->{"WRITE"}{"Length"})/0x1000)-1) {
+		IRP_MJ_WRITE_leave_page tohex(eval($Object->{"WRITE"}{"ByteOffset"})+0x1000*$reloffs),\@Lsn_check;
+		}
+
+	if ($LastLeave->{"by"} eq "FlushToLsnRoutine" && (my $FlushToLsnRoutine=$LastLeave)) {
+		my $Lsn_max;
+		for (@Lsn_check) {
+			my $Lsn=eval $_->{"Bcb_Lsn"};
+			$Lsn_max=$Lsn if !defined($Lsn_max) || $Lsn_max<$Lsn;
+			}
+		warn "FlushToLsnRoutine of line_enter ".$FlushToLsnRoutine->{"line_enter"}
+						." got Lsn ".$FlushToLsnRoutine->{"Lsn"}." although Bcbs have "
+						.join(",",map({ "(".$_->{"Bcb"}.":".$_->{"Bcb_Lsn"}.")"; } @Lsn_check))
+				if tohex($Lsn_max) ne $FlushToLsnRoutine->{"Lsn"};
+		}
+}
+
+sub IRP_MJ_READ_leave()
+{
+	# toplevel IRP_MJ_READ has no requirements
+	return if 0==@$EnterLeave;
+	my @stack=map({ $_->{"by"}=~/^IRP_MJ_/ ? () : $_ } @$EnterLeave);
+	my $opObject=$stack[0] if 1==@stack;
+	warn "IRP_MJ_READ not the expected function stack"
+						." (".join(",",map({ $_->{"line_enter"}.":".$_->{"by"}; } @$EnterLeave)).")"
+			if !($opObject->{"by"} eq "CcMapData"
+			  || $opObject->{"by"} eq "CcCopyRead"
+			  || $opObject->{"by"} eq "CcMdlRead"
+			  || $opObject->{"by"} eq "CcPinRead");
+	if ($opObject->{"by"} eq "CcMdlRead") {
+		do { warn "Length $_ not divisible by 0x1000" if eval($_)%0x1000; } for ($Object->{"READ"}{"Length"});
+		}
+	else {
+		do { warn "Length $_ not 0x1000" if eval($_)!=0x1000; } for ($Object->{"READ"}{"Length"});
+		}
+	my $SharedCacheMap=$Object->{"data"}[0]{"SharedCacheMap"};
+	return if !(my $CObject=CObject $SharedCacheMap);
+	for my $reloffs (0..eval($Object->{"READ"}{"Length"})/0x1000-1) {
+		my $ByteOffset=tohex(eval($Object->{"READ"}{"ByteOffset"})+$reloffs*0x1000);
+		# Do not: warn "Reading ByteOffset $ByteOffset into SharedCacheMap $SharedCacheMap twice"
+		#             if $CObject->{"in_memory"}{$ByteOffset};
+		# as it may be still cached there as Cache Manager is not forced to drop it.
+		$CObject->{"in_memory"}{$ByteOffset}=1;
+#		warn "MARK: SharedCacheMap ".$CObject->{"SharedCacheMap"}." FileOffset $ByteOffset";
+		}
+}
+
+sub CcPurgeCacheSection($$$$$)
+{
+my($SectionObjectPointer,$SharedCacheMap,$FileOffset,$Length,$UninitializeCacheMaps)=@_;
+
+	return if !(my $CObject=CObject $SharedCacheMap);
+	warn "Unexpected UninitializeCacheMaps $UninitializeCacheMaps" if $UninitializeCacheMaps ne "0";
+	my $all=($FileOffset eq "0x".("F"x8) && !eval $Length);
+	warn "Not yet implemented ranged CcPurgeCacheSection()" if !$all;
+	do { warn "Existing map Bcb $_ during CcPurgeCacheSection()" if $_; } for ($CObject->{"map"});
+	do { warn "Existing pin Bcb $_ during CcPurgeCacheSection()" if $_; } for (values(%{$CObject->{"pin"}}));
+	# Primary goal of this function:
+	delete $CObject->{"in_memory"};
+	# Really needed:
+	delete $CObject->{"Buffer"};
+}
+
+sub CcFlushCache($$$$)
+{
+my($SectionObjectPointer,$SharedCacheMap,$FileOffset,$Length)=@_;
+
+	$Object->{"CcFlushCached"}=0;
+	$Object->{"FileOffset"}=$FileOffset;
+	$Object->{"Length"}=$Length;
+}
+
+sub CcFlushCache_leave($$)
+{
+my($Status,$Information)=@_;
+
+	warn "CcFlushCache() not the toplevel function"
+						." (".join(",",map({ $_->{"line_enter"}.":".$_->{"by"}; } @$EnterLeave)).")"
+			if !(0==@$EnterLeave
+			 || (1==@$EnterLeave && ${$EnterLeave}[0]->{"by"}=~/^IRP_MJ_/));
+	if ($Status ne "0x".("F"x8) || $Information ne "0x".("F"x8)) {
+		warn "Unexpected Status $Status" if eval $Status;
+		warn "Unexpected Information $Information while CcFlushCached=".$Object->{"CcFlushCached"}
+				if eval($Information)!=eval($Object->{"CcFlushCached"})*0x1000;
+		}
+}
+
+sub CcPrepareMdlWrite($$$)
+{
+my($FileObject,$FileOffset,$Length)=@_;
+
+	$Object->{"FileObject"}=$FileObject;
+	warn "FileOffset $FileOffset not divisible by 0x1000" if eval($FileOffset)%0x1000;
+	$Object->{"FileOffset"}=$FileOffset;
+	warn "Length $Length not divisible by 0x1000" if eval($Length)%0x1000;
+	$Object->{"Length"}=$Length;
+}
+
+sub CcPrepareMdlWrite_leave($$$)
+{
+my($MdlChain,$Status,$Information)=@_;
+
+	do { warn "Unexpected Status $Status"; return; } if eval $Status;
+	warn "Unexpected Information $Information" if $Information ne $Object->{"Length"};
+	warn "MdlChain $MdlChain already exists" if $MdlChain{$MdlChain};
+	$MdlChain{$MdlChain}=$Object;
+}
+
+sub CcMdlWriteComplete($$$)
+{
+my($FileObject,$FileOffset,$MdlChain)=@_;
+
+	return if !(my $MObject=MObject $MdlChain);
+	warn "CcMdlWriteComplete() parameter FileObject $FileObject"
+					." not matching MdlChain $MdlChain FileObject ".$MObject->{"FileObject"}
+			if $FileObject ne $MObject->{"FileObject"};
+	warn "CcMdlWriteComplete() parameter FileOffset $FileOffset"
+					." not matching MdlChain $MdlChain FileOffset ".$MObject->{"FileOffset"}
+			if $FileOffset ne $MObject->{"FileOffset"};
+	# Propose MdlChain to a simulated Bcb.
+	# We must split it by pages as pin can be just 0x1000 sized.
+	return if !(my $CObject=CObject_from_FileObject $MObject->{"FileObject"});
+	for my $reloffs (0..eval($MObject->{"Length"})/0x1000-1) {
+		my $BObject={ %$MObject };
+		$BObject->{"Bcb"}="MdlChain $MdlChain reloffs $reloffs";
+		$BObject->{"FileOffset"}=tohex(eval($MObject->{"FileOffset"})+$reloffs*0x1000);
+		$BObject->{"SharedCacheMap"}=$CObject->{"SharedCacheMap"};
+		$BObject->{"type"}="pin";
+		$BObject->{"ref_count"}=0;
+		$BObject->{"dirty"}=1;
+		warn "Bcb ".$BObject->{"Bcb"}." already exists" if $Bcb{$BObject->{"Bcb"}};
+		$Bcb{$BObject->{"Bcb"}}=$BObject;
+		}
+	delete $MdlChain{$MdlChain};
+}
+
+sub CcMdlWriteAbort($$)
+{
+my($FileObject,$MdlChain)=@_;
+
+	warn "CcMdlWriteAbort() not handled";
+}
+
+sub AcquireForLazyWrite_leave($)
+{
+my($r)=@_;
+
+	warn "Unexpected 'r' $r" if $r ne "1";
+	warn "AcquireForLazyWrite() not the toplevel function" if @$EnterLeave;
+	return if !(my $CObject=CObject $Object->{"data"}[0]{"SharedCacheMap"});
+	$CObject->{"AcquireForLazyWrite"}++;
+}
+
+sub ReleaseFromLazyWrite_leave()
+{
+	warn "ReleaseFromLazyWrite() not the toplevel function" if @$EnterLeave;
+	return if !(my $CObject=CObject $Object->{"data"}[0]{"SharedCacheMap"});
+	warn "Invalid 'AcquireForLazyWrite' value ".$CObject->{"AcquireForLazyWrite"}
+			if !($CObject->{"AcquireForLazyWrite"}>=1);
+	$CObject->{"AcquireForLazyWrite"}--;
 }
 
 sub CcRemapBcb($)
@@ -630,25 +1058,20 @@ sub unpin($)
 my($Bcb)=@_;
 
 	return if !(my $BObject=BObject $Bcb);
-	delete $BObject->{"CcPinMappedData_double"};
 	return if --$BObject->{"ref_count"};
-	return if !(my $CObject=CObject $BObject->{"SharedCacheMap"});
-	if ($BObject->{"type"} eq "map") {
-		for my $pin (values(%{$CObject->{"pin"}})) {
-			warn "unpin map but CcPinMappedData pin $pin still exists"
-					if $Bcb{$pin}->{"by"} eq "CcPinMappedData";
-			}
-		}
-	for my $ref ($BObject->{"type"} eq "map" ? \$CObject->{"map"} : \$CObject->{"pin"}{$BObject->{"FileOffset"}}) {
-		warn "Final unpin but ".$BObject->{"type"}." Bcb $Bcb not registered"
-						." in SharedCacheMap ".$CObject->{"SharedCacheMap"}." ref ".($$ref || "<undef>")
-				if !defined($BObject->{"OwnerPointer"}) && !($$ref && $$ref eq $Bcb);
-		if ($$ref && $$ref eq $Bcb) {
-			$$ref=undef();
-			delete $CObject->{"pin"}{$BObject->{"FileOffset"}} if $BObject->{"type"} eq "pin";
-			}
+	if ($BObject->{"dirty"}) {
+		# last unpin of unreferenced dirty Bcb will no longer allow reincarnation
+		# of the same Bcb to the pin map of its SharedCacheMap.
+		return if !(my $CObject=CObject $BObject->{"SharedCacheMap"});
+		warn "unpin() of pin Bcb $Bcb but it is already not registered in SharedCacheMap ".$BObject->{"SharedCacheMap"}." pin map"
+				if (!$CObject->{"pin"}{$BObject->{"FileOffset"}} || $CObject->{"pin"}{$BObject->{"FileOffset"}} ne $Bcb)
+						&& !$BObject->{"OwnerPointer"};
+		delete $CObject->{"pin"}{$BObject->{"FileOffset"}}
+				if $CObject->{"pin"}{$BObject->{"FileOffset"}} && ($CObject->{"pin"}{$BObject->{"FileOffset"}} eq $Bcb);
+		CObject_Buffer_check $CObject;
+		return;
 		}
-	delete $Bcb{$Bcb};
+	delete_BObject $BObject;
 }
 
 sub CcUnpinData($)
@@ -677,6 +1100,7 @@ my($Bcb,$OwnerPointer)=@_;
 	warn "CcSetBcbOwnerPointer() on unregistered pin Bcb $Bcb" if !$val || $val ne $Bcb;
 	delete $CObject->{"pin"}{$BObject->{"FileOffset"}} if $val && $val eq $Bcb;
 	$BObject->{"OwnerPointer"}=$OwnerPointer;
+	CObject_Buffer_check $CObject;
 }
 
 sub IRP_MJ_CLOSE_leave()
@@ -696,39 +1120,39 @@ sub IRP_MJ_CLOSE_leave()
 #					if $SectionObjectPointer && $CObject->{"ref_count"};
 			}
 		}
-	delete $FileObject{$FileObject};
+	delete_FObject $FObject;
 }
 
 
 local $_;
 my $hex='0x[\dA-F]+';
 my %last_irp_mj;
-my %enter_leave;
 while (<>) {
 	chomp;
 	s/\r$//;
 	# We may get some foreign garbage without '\n' before our debug data line:
 	# Do not use '\bTraceFS' as there really can be precediny _any_ data.
 	s#^.*?TraceFS[(]($hex/$hex)[)]: ## or do { print "$_\n" if $filter; next; };
-	my($process_thread)=($1);
+	$ProcessThread=$1;
 
 	$Object=undef();
 	if (/^enter: (\w+)/) {
 		$Object={};
 		$Object->{"by"}=$1;
 		$Object->{"line_enter"}=$.;
-		$Object->{"process_thread"}=$process_thread;
-		push @{$enter_leave{$process_thread}},$Object;
+		$Object->{"ProcessThread"}=$ProcessThread;
+		push @{$EnterLeave{$ProcessThread}},$Object;
 		}
 	elsif (/^leave: (\w+)/) {
-		warn "Empty pop stack during 'leave' of $1" if !($Object=pop @{$enter_leave{$process_thread}});
+		warn "Empty pop stack during 'leave' of $1" if !($Object=pop @{$EnterLeave{$ProcessThread}});
 		warn "Non-matching popped 'by' ".$Object->{"by"}." ne current 'leave' $1"
 				if $Object->{"by"} ne $1;
 		$Object->{"line_leave"}=$.;
+		push @{$LastLeave{$ProcessThread}},$Object;
 		}
 	elsif (my($FileObject,$FileName,$Flags,$SectionObjectPointer,$SharedCacheMap)=
-			/^FileObject=($hex): FileName=(?:NULL|'(.*)'),Flags=($hex),SectionObjectPointer=($hex),->SharedCacheMap=($hex)/) {
-		my $aref=$enter_leave{$process_thread};
+			/^FileObject=($hex): FileName=(?:NULL|'(.*)'),(?:ref=[+-]\d+,)?Flags=($hex),SectionObjectPointer=($hex),->SharedCacheMap=($hex)/) {
+		my $aref=$EnterLeave{$ProcessThread};
 		warn "Empty stack during 'data' line" if !($Object=${$aref}[$#$aref]);
 		my $data={
 				"FileObject"=>$FileObject,
@@ -785,6 +1209,19 @@ while (<>) {
 			}
 		next;
 		}
+	elsif (my($op,$ByteOffset,$Length)=
+			/^(READ|WRITE): ByteOffset=($hex),Length=($hex)/) {
+		my $aref=$EnterLeave{$ProcessThread};
+		warn "Empty stack during 'data' line" if !($Object=${$aref}[$#$aref]);
+		$Object->{$op}={
+			"ByteOffset"=>$ByteOffset,
+			"Length"=>$Length,
+			};
+		next;
+		}
+
+	$LastLeave=${$LastLeave{$ProcessThread}}[$#{$LastLeave{$ProcessThread}}-1];
+	$EnterLeave=$EnterLeave{$ProcessThread};
 
 	if (my($r)=
 			/^leave: IRP_MJ_\w+: r=($hex)/) {
@@ -879,6 +1316,78 @@ while (<>) {
 		next;
 		}
 
+	if (my($LogHandle,$Lsn)=
+			/^enter: FlushToLsnRoutine: LogHandle=($hex),Lsn=($hex)/) {
+		FlushToLsnRoutine $LogHandle,$Lsn;
+		next;
+		}
+
+	if (/^leave: IRP_MJ_READ\b/) {
+		IRP_MJ_READ_leave;
+		next;
+		}
+
+	if (my($SectionObjectPointer,$SharedCacheMap,$FileOffset,$Length,$UninitializeCacheMaps)=
+		/^enter: CcPurgeCacheSection: SectionObjectPointer=($hex),->SharedCacheMap=($hex),FileOffset=($hex),Length=($hex),UninitializeCacheMaps=([01])/) {
+		CcPurgeCacheSection $SectionObjectPointer,$SharedCacheMap,$FileOffset,$Length,$UninitializeCacheMaps;
+		next;
+		}
+
+	if (/^leave: IRP_MJ_WRITE\b/) {
+		IRP_MJ_WRITE_leave;
+		next;
+		}
+
+	if (my($SectionObjectPointer,$SharedCacheMap,$FileOffset,$Length)=
+			/^enter: CcFlushCache: SectionObjectPointer=($hex),->SharedCacheMap=($hex),FileOffset=($hex),Length=($hex)/) {
+		CcFlushCache $SectionObjectPointer,$SharedCacheMap,$FileOffset,$Length;
+		next;
+		}
+
+	if (my($Status,$Information)=
+			/^leave: CcFlushCache: IoStatus->Status=($hex),IoStatus->Information=($hex)/) {
+		CcFlushCache_leave $Status,$Information;
+		next;
+		}
+
+	if (my($r)=
+			/^leave: AcquireForLazyWrite: r=([01])/) {
+		AcquireForLazyWrite_leave $r;
+		}
+
+	if (/^leave: ReleaseFromLazyWrite\b/) {
+		ReleaseFromLazyWrite_leave;
+		}
+
+	if (my($FileObject,$LogHandle,$FlushToLsnRoutine)=
+			/^enter: CcSetLogHandleForFile: FileObject=($hex),LogHandle=($hex),FlushToLsnRoutine=($hex)/) {
+		CcSetLogHandleForFile $FileObject,$LogHandle,$FlushToLsnRoutine;
+		next;
+		}
+
+	if (my($FileObject,$FileOffset,$Length)=
+			/^enter: CcPrepareMdlWrite: FileObject=($hex),FileOffset=($hex),Length=($hex)/) {
+		CcPrepareMdlWrite $FileObject,$FileOffset,$Length;
+		next;
+		}
+	if (my($MdlChain,$Status,$Information)=
+			/^leave: CcPrepareMdlWrite: MdlChain=($hex),IoStatus->Status=($hex),IoStatus->Information=($hex)/) {
+		CcPrepareMdlWrite_leave $MdlChain,$Status,$Information;
+		next;
+		}
+
+	if (my($FileObject,$FileOffset,$MdlChain)=
+			/^enter: CcMdlWriteComplete: FileObject=($hex),FileOffset=($hex),MdlChain=($hex)/) {
+		CcMdlWriteComplete $FileObject,$FileOffset,$MdlChain;
+		next;
+		}
+
+	if (my($FileObject,$MdlChain)=
+			/^enter: CcMdlWriteAbort: FileObject=($hex),MdlChain=($hex)/) {
+		CcMdlWriteAbort $FileObject,$MdlChain;
+		next;
+		}
+
 	if (my($Bcb)=
 			/^enter: CcRemapBcb: Bcb=($hex)/) {
 		CcRemapBcb $Bcb;