[SERVER-62420] TTL monitoring logs on system profile Created: 07/Jan/22  Updated: 12/May/22  Resolved: 12/May/22

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 5.0.4
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Pierre-Jean Martin Assignee: Dmitry Agranat
Resolution: Done Votes: 0
Labels: Bug
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Steps To Reproduce:

From mongosh :

  • run `use database-test`
  • run `db.setProfilingLevel(2)`
  • run `db.eventlog.createIndex( { "lastModifiedDate": 1 }, { expireAfterSeconds: 30 } )`
  • run `db.eventlog.insertOne({ lastModifiedDate: new Date() })`
  • Wait one minute
  • run `db.system.profile.find()`
  • There are no information about TTL monitoring
Participants:

 Description   

Hello,

I'm using TTL Indexes (https://docs.mongodb.com/manual/core/index-ttl/#expiration-of-data) The deleting works fine but I want to log the data removed.

The doc say : `When the TTL thread is active, you will see delete operations in the output of db.currentOp() or in the data collected by the database profiler.` 

When I display the system profile, There are no information about the TTL and I need to log the trace of the remove.

I set the profiling level to 2.

Do you know if it's a bug or I didn't understand the monitoring ?



 Comments   
Comment by Brooke Miller [ 12/May/22 ]

Hi pj-martin@outlook.fr,

We haven’t heard back from you for some time, so I’m going to close this ticket. If this is still an issue for you, please provide additional information and we will reopen the ticket.

Regards,

Brooke

Comment by Dmitry Agranat [ 16/Feb/22 ]

pj-martin@outlook.fr, do you need any more input from our side?

Comment by Dmitry Agranat [ 25/Jan/22 ]

Hi pj-martin@outlook.fr, I am unable to reproduce this issue:

MongoDB Enterprise SERVER-62420:PRIMARY> show dbs
admin   0.000GB
config  0.000GB
local   0.003GB
test    0.000GB
MongoDB Enterprise SERVER-62420:PRIMARY> use test
switched to db test
MongoDB Enterprise SERVER-62420:PRIMARY> db.setProfilingLevel(2)
{
	"was" : 0,
	"slowms" : 100,
	"sampleRate" : 1,
	"ok" : 1,
	"$clusterTime" : {
		"clusterTime" : Timestamp(1643108825, 1),
		"signature" : {
			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
			"keyId" : NumberLong(0)
		}
	},
	"operationTime" : Timestamp(1643108825, 1)
}
MongoDB Enterprise SERVER-62420:PRIMARY> db.getProfilingStatus()
{
	"was" : 2,
	"slowms" : 100,
	"sampleRate" : 1,
	"$clusterTime" : {
		"clusterTime" : Timestamp(1643108885, 1),
		"signature" : {
			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
			"keyId" : NumberLong(0)
		}
	},
	"operationTime" : Timestamp(1643108885, 1)
}
MongoDB Enterprise SERVER-62420:PRIMARY> db.eventlog.createIndex( { "lastModifiedDate": 1 }, { expireAfterSeconds: 30 } )
{
	"numIndexesBefore" : 1,
	"numIndexesAfter" : 2,
	"createdCollectionAutomatically" : true,
	"commitQuorum" : "votingMembers",
	"ok" : 1,
	"$clusterTime" : {
		"clusterTime" : Timestamp(1643108932, 2),
		"signature" : {
			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
			"keyId" : NumberLong(0)
		}
	},
	"operationTime" : Timestamp(1643108932, 2)
}
MongoDB Enterprise SERVER-62420:PRIMARY> db.eventlog.insertOne({ lastModifiedDate: new Date() })
{
	"acknowledged" : true,
	"insertedId" : ObjectId("61efda57c69556b30de167c2")
}
MongoDB Enterprise SERVER-62420:PRIMARY> db.system.profile.find()
{ "op" : "command", "ns" : "test.eventlog", "command" : { "createIndexes" : "eventlog", "indexes" : [ { "key" : { "lastModifiedDate" : 1 }, "name" : "lastModifiedDate_1", "expireAfterSeconds" : 30 } ], "lsid" : { "id" : UUID("52b245af-6931-4b34-96bb-a45525ce064c") }, "$clusterTime" : { "clusterTime" : Timestamp(1643108885, 1), "signature" : { "hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="), "keyId" : NumberLong(0) } }, "$db" : "test" }, "numYield" : 0, "locks" : { "ParallelBatchWriterMode" : { "acquireCount" : { "r" : NumberLong(4) } }, "ReplicationStateTransition" : { "acquireCount" : { "w" : NumberLong(4) } }, "Global" : { "acquireCount" : { "r" : NumberLong(3), "w" : NumberLong(1) } }, "Database" : { "acquireCount" : { "r" : NumberLong(3), "w" : NumberLong(1) } }, "Collection" : { "acquireCount" : { "r" : NumberLong(2), "w" : NumberLong(1) } }, "Mutex" : { "acquireCount" : { "r" : NumberLong(4) } } }, "flowControl" : {  }, "responseLength" : 271, "protocol" : "op_msg", "millis" : 13, "ts" : ISODate("2022-01-25T11:08:52.932Z"), "client" : "127.0.0.1", "appName" : "MongoDB Shell", "allUsers" : [ ], "user" : "" }
{ "op" : "insert", "ns" : "test.eventlog", "command" : { "insert" : "eventlog", "ordered" : true, "lsid" : { "id" : UUID("52b245af-6931-4b34-96bb-a45525ce064c") }, "$clusterTime" : { "clusterTime" : Timestamp(1643108932, 2), "signature" : { "hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="), "keyId" : NumberLong(0) } }, "$db" : "test" }, "ninserted" : 1, "keysInserted" : 2, "numYield" : 0, "locks" : { "ParallelBatchWriterMode" : { "acquireCount" : { "r" : NumberLong(1) } }, "ReplicationStateTransition" : { "acquireCount" : { "w" : NumberLong(1) } }, "Global" : { "acquireCount" : { "w" : NumberLong(1) } }, "Database" : { "acquireCount" : { "w" : NumberLong(1) } }, "Collection" : { "acquireCount" : { "w" : NumberLong(1) } }, "Mutex" : { "acquireCount" : { "r" : NumberLong(1) } } }, "flowControl" : { "acquireCount" : NumberLong(1), "timeAcquiringMicros" : NumberLong(1) }, "responseLength" : 230, "protocol" : "op_msg", "millis" : 0, "ts" : ISODate("2022-01-25T11:09:11.629Z"), "client" : "127.0.0.1", "appName" : "MongoDB Shell", "allUsers" : [ ], "user" : "" }

Can you run the same commands as I did and post the same output? Please also mention the MongoDB version used. In my example above, I was using 5.0.5.

Generated at Thu Feb 08 05:55:05 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.