[SERVER-29102] WiredTiger does not rotate journal log files Created: 08/May/17  Updated: 21/Jul/17  Resolved: 18/May/17

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

Type: Bug Priority: Major - P3
Reporter: Juan Antonio Roy Couto Assignee: Susan LoVerso
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

SO: Ubuntu 16.04.2 LTS (GNU/Linux 4.4.0-75-generic x86_64)
file system: XFS
ram: 4GB
swap: 20GB
disk: 50GB (/dev/vda1)
cores: 16
undanet@susanpre03:~$ mongo --version
MongoDB shell version v3.4.2
git version: 3f76e40c105fc223b3e5aac3e20dcd026b83b38b
OpenSSL version: OpenSSL 1.0.2g 1 Mar 2016
allocator: tcmalloc
modules: none
build environment:
distmod: ubuntu1604
distarch: x86_64
target_arch: x86_64
undanet@susanpre03:~$


Attachments: PNG File 29102.bigvals.png     File WiredTigerJournalError20170507.tar.gz     File syslog.20170429.gz    
Issue Links:
Documented
is documented by DOCS-10562 Add warning about using WiredTiger wi... Closed
Related
related to WT-3327 Checkpoints can hang if time runs bac... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Sprint: Storage 2017-05-29
Participants:

 Description   

I have problems with the "/var/lib/mongodb/journal$" directory due to WiredTiger creates more than three files. More or less, it creates a new file per 30 minutes.

The disk is going to be full and mongod will not be able to write any operations.

Thank you very much for your help!



 Comments   
Comment by Juan Antonio Roy Couto [ 18/May/17 ]

I have eliminated these messages and everything looks fine.
I will let you know if the problems with WiredTiger journal log files arise again.
Thank you very much!

Comment by Juan Antonio Roy Couto [ 17/May/17 ]

Hi Bruce Lucas
Yes, we use Hyper-V!
Ok, I'll let you know.
Thank you!

Comment by Bruce Lucas (Inactive) [ 17/May/17 ]

Hi Juan,

The syslog that you uploaded shows frequent messages like this:

May  1 06:25:49 susanpre03 systemd[1]: Time has been changed

A google search for that message turned up this page with someone who had a similar problem and what they did to fix it. They were running under Windows Hyper-V, but even if that is not your case maybe this will provide a clue to fix your problem.

https://askubuntu.com/questions/888493/var-log-syslog-systemd1-time-has-been-changed-message-every-5-seconds

Once you have eliminated the "Time has been changed" messages from syslog, please let us know if that resolves your other problems.

Comment by Juan Antonio Roy Couto [ 17/May/17 ]

Hi, Sue LoVerso
This node is running on a Virtual Machine.
I have not any daemon like ntp.
It is true that we have had problems with time. I think we have three different times, let's see:
$ timedatectl
Local time: mié 2017-05-17 15:42:14 CEST
Universal time: mié 2017-05-17 13:42:14 UTC
RTC time: mié 2017-05-17 13:48:22
Time zone: Europe/Madrid (CEST, +0200)
Network time on: yes
NTP synchronized: yes
RTC in local TZ: no
$
Could a ntp daemon resolve these problems?

Comment by Susan LoVerso [ 17/May/17 ]

Can you describe the system you're running on? Is it a virtual machine? Or an AWS instance or some other cloud instance?

Comment by Susan LoVerso [ 16/May/17 ]

juanroy Looking at this, the error paths I referred to earlier are correct. However one thing that could explain the values we see is if the system time went backward. Are you running some kind of time daemon process like ntpd or something similar? Could time be getting adjusted backward?

Comment by Juan Antonio Roy Couto [ 16/May/17 ]

Sue LoVerso I do not have that system log but I have one of another day I issued the same problem. Perhaps It can help us. In it I can see:

Apr 29 23:55:14 susanpre03 systemd[1]: mongod.service: Main process exited, code=killed, status=6/ABRT
Apr 29 23:55:14 susanpre03 systemd[1]: mongod.service: Unit entered failed state.
Apr 29 23:55:14 susanpre03 systemd[1]: mongod.service: Failed with result 'signal'.

I've attached it!

Thanks

Comment by Susan LoVerso [ 16/May/17 ]

Looking more closely at this, I suspect that the wildly large values indicate disk errors (and a bug in the error path handling that doesn't stop some timers). For example I see that if the logging code performing an fsync gets an error it doesn't clear the timer. juanroy if you have access to system logs from this timeframe can you check if there are any errors reported?

Comment by Susan LoVerso [ 08/May/17 ]

There are definitely some wild values in the metrics. Before I get to that, here's what I found:

  • They sent three log files, 479, 511, 512. Log file 479 has checkpoint records in it, so that is why earlier log files were archived.
  • Log files 511 and 512 do not have any checkpoint records in them. Presumably neither do log file 480-510. I don't believe the "not removing log files" part of this is indicating a bug in the archive code.
  • The dates on the log files shown in WiredTigerJournalError20170507/WiredTigerJournalFiles/*txt indicates that log file 479 was last written at May 7, 22:45. The other log files fill up every 5-35 minutes later.
  • The turtle file in the tarball has the last checkpoint in line with that: checkpoint=(WiredTigerCheckpoint.7767=(addr="018381e40a7c9a788481e42d0d39938581e457578178808080e301cfc0e29fc0",order=7767,time=1494189850,size=53248,write_gen=24023)),checkpoint_lsn=(479,90348800)
    • The timestamp of 1494189850 is May 7 22:44:10.
  • The metrics show a checkpoint starts and never completes. The wild values begin back on May 3.
  • There were only 5 other checkpoints between May 3 and the never-completing one on May 7 (at least ones lasting long enough to show up in the "checkpoint currently running" statistic).
Comment by Juan Antonio Roy Couto [ 08/May/17 ]

Hi!
We have rebooted the machine and just now I only have three files at the "/var/lib/mongodb/journal" directory
Thx

Generated at Thu Feb 08 04:19:54 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.