mirror of
https://github.com/enso-org/enso.git
synced 2024-12-23 09:22:41 +03:00
Log timings of FS operations (#9908)
I'm seeing occasional IO timeouts, especially on startup operations, for cloud projects. Adding some logging to make an informed decision if there are some problems there. Related to https://github.com/enso-org/enso/issues/9789 # Important Notes Also added retries when closing the file as I saw a number of times: ``` Session release failed. LsRpcError: Language server request 'text/closeFile' failed. at LanguageServer.request (/tmp/.mount_enso-leMqqdS/resources/app.asar/index.cjs:58291:15) at async Promise.all (index 0) at async _LanguageServerSession.release (/tmp/.mount_enso-leMqqdS/resources/app.asar/index.cjs:59165:5) at async /tmp/.mount_enso-leMqqdS/resources/app.asar/index.cjs:59670:7 { cause: JSONRPCError2: Request timeout request took longer than 15000 ms to resolve at new JSONRPCError2 (/tmp/.mount_enso-leMqqdS/resources/app.asar/index.cjs:26822:30) at Timeout._onTimeout (/tmp/.mount_enso-leMqqdS/resources/app.asar/index.cjs:26985:20) at listOnTimeout (node:internal/timers:569:17) at process.processTimers (node:internal/timers:512:7) { code: 7777, data: undefined }, request: 'text/closeFile', params: { path: { rootId: '00000000-0000-0000-0000-000000000001', segments: [Array] } } } ```
This commit is contained in:
parent
1d8fc1bf6e
commit
f1ddf1b863
@ -123,7 +123,7 @@ class MainModule(serverConfig: LanguageServerConfig, logLevel: Level) {
|
||||
private val zioExec = effect.ZioExec(zioRuntime)
|
||||
log.trace("Created ZIO executor [{}].", zioExec)
|
||||
|
||||
private val fileSystem: FileSystem = new FileSystem
|
||||
private val fileSystem: FileSystem = new FileSystem(log)
|
||||
log.trace("Created file system [{}].", fileSystem)
|
||||
|
||||
val git = Git.withEmptyUserConfig(
|
||||
|
@ -2,6 +2,7 @@ package org.enso.languageserver.filemanager
|
||||
|
||||
import org.apache.commons.io.{FileExistsException, FileUtils}
|
||||
import org.enso.languageserver.effect.BlockingIO
|
||||
import org.slf4j.Logger
|
||||
import zio._
|
||||
|
||||
import java.io.{File, FileNotFoundException, RandomAccessFile}
|
||||
@ -15,7 +16,7 @@ import zio.ZIO.attemptBlocking
|
||||
|
||||
/** File manipulation facility.
|
||||
*/
|
||||
class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
class FileSystem(logger: Logger) extends FileSystemApi[BlockingIO] {
|
||||
|
||||
private val tenMb: Int = 1 * 1024 * 1024 * 10
|
||||
|
||||
@ -34,7 +35,9 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
file: File,
|
||||
content: String
|
||||
): BlockingIO[FileSystemFailure, Unit] =
|
||||
attemptBlocking(FileUtils.write(file, content, "UTF-8"))
|
||||
timedBlockingOp("writeTextToFile", logger) {
|
||||
FileUtils.write(file, content, "UTF-8")
|
||||
}
|
||||
.mapError(errorHandling)
|
||||
|
||||
/** @inheritdoc */
|
||||
@ -42,7 +45,9 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
file: File,
|
||||
contents: Array[Byte]
|
||||
): BlockingIO[FileSystemFailure, Unit] =
|
||||
attemptBlocking(FileUtils.writeByteArrayToFile(file, contents))
|
||||
timedBlockingOp("writeBytesToFile", logger) {
|
||||
FileUtils.writeByteArrayToFile(file, contents)
|
||||
}
|
||||
.mapError(errorHandling)
|
||||
|
||||
/** Reads the contents of a textual file.
|
||||
@ -51,14 +56,16 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
* @return either [[FileSystemFailure]] or the content of a file as a String
|
||||
*/
|
||||
override def read(file: File): BlockingIO[FileSystemFailure, String] =
|
||||
attemptBlocking(FileUtils.readFileToString(file, "UTF-8"))
|
||||
timedBlockingOp("readFile", logger) {
|
||||
FileUtils.readFileToString(file, "UTF-8")
|
||||
}
|
||||
.mapError(errorHandling)
|
||||
|
||||
/** @inheritdoc */
|
||||
override def readBinary(
|
||||
file: File
|
||||
): BlockingIO[FileSystemFailure, Array[Byte]] =
|
||||
attemptBlocking(FileUtils.readFileToByteArray(file))
|
||||
timedBlockingOp("readBytes", logger) { FileUtils.readFileToByteArray(file) }
|
||||
.mapError(errorHandling)
|
||||
|
||||
/** Deletes the specified file or directory recursively.
|
||||
@ -67,7 +74,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
* @return either [[FileSystemFailure]] or Unit
|
||||
*/
|
||||
def delete(file: File): BlockingIO[FileSystemFailure, Unit] =
|
||||
attemptBlocking {
|
||||
timedBlockingOp("deletePath", logger) {
|
||||
if (file.isDirectory) {
|
||||
FileUtils.deleteDirectory(file)
|
||||
} else {
|
||||
@ -87,7 +94,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
} yield ()
|
||||
|
||||
private def createEmptyFile(file: File): BlockingIO[FileSystemFailure, Unit] =
|
||||
attemptBlocking(file.createNewFile(): Unit)
|
||||
timedBlockingOp("createEmptyFile", logger) { file.createNewFile(): Unit }
|
||||
.mapError(errorHandling)
|
||||
|
||||
/** Creates a directory, including any necessary but nonexistent parent
|
||||
@ -99,7 +106,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
override def createDirectory(
|
||||
file: File
|
||||
): BlockingIO[FileSystemFailure, Unit] =
|
||||
attemptBlocking(FileUtils.forceMkdir(file))
|
||||
timedBlockingOp("digestBytes", logger) { FileUtils.forceMkdir(file) }
|
||||
.mapError(errorHandling)
|
||||
|
||||
/** Copy a file or directory recursively.
|
||||
@ -114,7 +121,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
if (from.isDirectory && to.isFile) {
|
||||
ZIO.fail(FileExists)
|
||||
} else {
|
||||
attemptBlocking {
|
||||
timedBlockingOp("copyFile", logger) {
|
||||
if (from.isFile && to.isDirectory) {
|
||||
FileUtils.copyFileToDirectory(from, to)
|
||||
} else if (from.isDirectory) {
|
||||
@ -132,7 +139,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
* @return either [[FileSystemFailure]] or Unit
|
||||
*/
|
||||
override def move(from: File, to: File): BlockingIO[FileSystemFailure, Unit] =
|
||||
attemptBlocking {
|
||||
timedBlockingOp("moveFile", logger) {
|
||||
if (to.isDirectory) {
|
||||
val createDestDir = false
|
||||
FileUtils.moveToDirectory(from, to, createDestDir)
|
||||
@ -149,7 +156,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
* @return either [[FileSystemFailure]] or file existence flag
|
||||
*/
|
||||
override def exists(file: File): BlockingIO[FileSystemFailure, Boolean] =
|
||||
attemptBlocking(Files.exists(file.toPath))
|
||||
timedBlockingOp("fileExists", logger) { Files.exists(file.toPath) }
|
||||
.mapError(errorHandling)
|
||||
|
||||
/** List contents of a given path.
|
||||
@ -160,7 +167,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
override def list(path: File): BlockingIO[FileSystemFailure, Vector[Entry]] =
|
||||
if (path.exists) {
|
||||
if (path.isDirectory) {
|
||||
attemptBlocking {
|
||||
timedBlockingOp("listPath", logger) {
|
||||
FileSystem
|
||||
.list(path.toPath)
|
||||
.map {
|
||||
@ -189,7 +196,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
val limit = FileSystem.Depth(depth)
|
||||
if (path.exists && limit.canGoDeeper) {
|
||||
if (path.isDirectory) {
|
||||
attemptBlocking {
|
||||
timedBlockingOp("tree", logger) {
|
||||
val directory = DirectoryEntry.empty(path.toPath)
|
||||
FileSystem.readDirectoryEntry(
|
||||
directory,
|
||||
@ -217,7 +224,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
path: File
|
||||
): BlockingIO[FileSystemFailure, Attributes] =
|
||||
if (path.exists) {
|
||||
attemptBlocking {
|
||||
timedBlockingOp("fileInfo", logger) {
|
||||
val attrs =
|
||||
Files.readAttributes(path.toPath, classOf[BasicFileAttributes])
|
||||
Attributes.fromBasicAttributes(path.toPath, attrs)
|
||||
@ -233,7 +240,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
*/
|
||||
override def digest(path: File): BlockingIO[FileSystemFailure, SHA3_224] = {
|
||||
if (path.isFile) {
|
||||
attemptBlocking {
|
||||
timedBlockingOp("digestFile", logger) {
|
||||
val messageDigest = MessageDigest.getInstance("SHA3-224")
|
||||
Using.resource(
|
||||
Files.newInputStream(path.toPath, StandardOpenOption.READ)
|
||||
@ -267,7 +274,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
): BlockingIO[FileSystemFailure, SHA3_224] = {
|
||||
val path = segment.path
|
||||
if (path.isFile) {
|
||||
attemptBlocking {
|
||||
timedBlockingOp("digestBytes", logger) {
|
||||
val messageDigest = MessageDigest.getInstance("SHA3-224")
|
||||
Using.resource(
|
||||
Files.newInputStream(path.toPath, StandardOpenOption.READ)
|
||||
@ -316,7 +323,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
if (path.isDirectory) {
|
||||
ZIO.fail(NotFile)
|
||||
} else {
|
||||
attemptBlocking {
|
||||
timedBlockingOp("writeBytes", logger) {
|
||||
Using.resource(new RandomAccessFile(path, "rw")) { file =>
|
||||
Using.resource(file.getChannel) { chan =>
|
||||
val lock = chan.lock()
|
||||
@ -366,7 +373,7 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
): BlockingIO[FileSystemFailure, ReadBytesResult] = {
|
||||
val path = segment.path
|
||||
if (path.isFile) {
|
||||
attemptBlocking {
|
||||
timedBlockingOp("readBytes", logger) {
|
||||
Using.resource(
|
||||
Files.newInputStream(path.toPath, StandardOpenOption.READ)
|
||||
) { stream =>
|
||||
@ -404,6 +411,22 @@ class FileSystem extends FileSystemApi[BlockingIO] {
|
||||
case FileSystem.CannotOverwrite => CannotOverwrite
|
||||
case ex => GenericFileSystemFailure(ex.getMessage)
|
||||
}
|
||||
|
||||
private def timedBlockingOp[T](opName: String, logger: Logger)(
|
||||
op: => T
|
||||
)(implicit trace: Trace): Task[T] = {
|
||||
attemptBlocking {
|
||||
val start = java.lang.System.currentTimeMillis()
|
||||
try {
|
||||
op
|
||||
} finally {
|
||||
if (logger.isTraceEnabled()) {
|
||||
val now = java.lang.System.currentTimeMillis();
|
||||
logger.trace(s"$opName took ${now - start} milliseconds")
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
object FileSystem {
|
||||
|
@ -1,15 +1,18 @@
|
||||
package org.enso.languageserver.requesthandler.text
|
||||
|
||||
import akka.actor.{Actor, ActorRef, Cancellable, Props}
|
||||
import akka.actor.{Actor, ActorRef, Props}
|
||||
import com.typesafe.scalalogging.LazyLogging
|
||||
import org.enso.jsonrpc._
|
||||
import org.enso.languageserver.requesthandler.RequestTimeout
|
||||
import org.enso.languageserver.session.JsonSession
|
||||
import org.enso.languageserver.text.TextApi.{CloseFile, FileNotOpenedError}
|
||||
import org.enso.languageserver.text.TextProtocol
|
||||
import org.enso.languageserver.text.{TextApi, TextProtocol}
|
||||
import org.enso.languageserver.text.TextProtocol.{FileClosed, FileNotOpened}
|
||||
import org.enso.languageserver.util.UnhandledLogging
|
||||
import org.enso.languageserver.util.{
|
||||
RequestHandlerWithRetries,
|
||||
UnhandledLogging
|
||||
}
|
||||
|
||||
import scala.concurrent.ExecutionContext
|
||||
import scala.concurrent.duration.FiniteDuration
|
||||
|
||||
/** A request handler for `text/closeFile` commands.
|
||||
@ -22,45 +25,36 @@ class CloseFileHandler(
|
||||
bufferRegistry: ActorRef,
|
||||
timeout: FiniteDuration,
|
||||
rpcSession: JsonSession
|
||||
) extends Actor
|
||||
) extends RequestHandlerWithRetries[
|
||||
Request[CloseFile.type, CloseFile.Params],
|
||||
FileClosed.type,
|
||||
FileNotOpened.type,
|
||||
TextProtocol.CloseFile
|
||||
](bufferRegistry, timeout, 5)
|
||||
with Actor
|
||||
with LazyLogging
|
||||
with UnhandledLogging {
|
||||
|
||||
import context.dispatcher
|
||||
|
||||
override def receive: Receive = requestStage
|
||||
|
||||
private def requestStage: Receive = {
|
||||
case Request(CloseFile, id, params: CloseFile.Params) =>
|
||||
bufferRegistry ! TextProtocol.CloseFile(rpcSession.clientId, params.path)
|
||||
val cancellable =
|
||||
context.system.scheduler.scheduleOnce(timeout, self, RequestTimeout)
|
||||
context.become(responseStage(id, sender(), cancellable))
|
||||
override protected def request(
|
||||
msg: Request[TextApi.CloseFile.type, CloseFile.Params]
|
||||
): TextProtocol.CloseFile = {
|
||||
TextProtocol.CloseFile(rpcSession.clientId, msg.params.path)
|
||||
}
|
||||
|
||||
private def responseStage(
|
||||
id: Id,
|
||||
override protected def positiveResponse(
|
||||
replyTo: ActorRef,
|
||||
cancellable: Cancellable
|
||||
): Receive = {
|
||||
case RequestTimeout =>
|
||||
logger.error(
|
||||
"Closing file request [{}] for [{}] timed out.",
|
||||
id,
|
||||
rpcSession.clientId
|
||||
)
|
||||
replyTo ! ResponseError(Some(id), Errors.RequestTimeout)
|
||||
context.stop(self)
|
||||
initialMsg: Request[TextApi.CloseFile.type, CloseFile.Params],
|
||||
msg: TextProtocol.FileClosed.type
|
||||
): Unit = {
|
||||
replyTo ! ResponseResult(CloseFile, initialMsg.id, Unused)
|
||||
}
|
||||
|
||||
case FileClosed =>
|
||||
replyTo ! ResponseResult(CloseFile, id, Unused)
|
||||
cancellable.cancel()
|
||||
context.stop(self)
|
||||
|
||||
case FileNotOpened =>
|
||||
replyTo ! ResponseError(Some(id), FileNotOpenedError)
|
||||
cancellable.cancel()
|
||||
context.stop(self)
|
||||
override protected def negativeResponse(
|
||||
replyTo: ActorRef,
|
||||
initialMsg: Request[TextApi.CloseFile.type, CloseFile.Params],
|
||||
error: TextProtocol.FileNotOpened.type
|
||||
)(implicit ec: ExecutionContext): Unit = {
|
||||
replyTo ! ResponseError(Some(initialMsg.id), FileNotOpenedError)
|
||||
}
|
||||
}
|
||||
|
||||
|
@ -13,6 +13,7 @@ import java.security.MessageDigest
|
||||
import scala.collection.mutable.ArrayBuffer
|
||||
import scala.io.Source
|
||||
import scala.jdk.CollectionConverters._
|
||||
import org.slf4j.LoggerFactory
|
||||
|
||||
class FileSystemSpec
|
||||
extends AnyWordSpecLike
|
||||
@ -1020,7 +1021,9 @@ class FileSystemSpec
|
||||
val testDirPath = Files.createTempDirectory(null)
|
||||
sys.addShutdownHook(FileUtils.deleteQuietly(testDirPath.toFile))
|
||||
|
||||
val objectUnderTest = new FileSystem
|
||||
val objectUnderTest = new FileSystem(
|
||||
LoggerFactory.getLogger(classOf[FileSystemSpec])
|
||||
)
|
||||
|
||||
}
|
||||
|
||||
|
@ -36,6 +36,7 @@ import org.enso.languageserver.websocket.binary.factory.{
|
||||
import java.util.concurrent.{ExecutorService, Executors}
|
||||
import scala.concurrent.ExecutionContext
|
||||
import scala.concurrent.duration._
|
||||
import org.slf4j.LoggerFactory
|
||||
|
||||
abstract class BaseBinaryServerTest extends BinaryServerTestKit {
|
||||
|
||||
@ -89,7 +90,9 @@ abstract class BaseBinaryServerTest extends BinaryServerTestKit {
|
||||
FileManager.props(
|
||||
config.fileManager,
|
||||
contentRootManagerWrapper,
|
||||
new FileSystem,
|
||||
new FileSystem(
|
||||
LoggerFactory.getLogger(classOf[BaseBinaryServerTest])
|
||||
),
|
||||
zioExec
|
||||
)
|
||||
)
|
||||
|
@ -73,6 +73,7 @@ import java.util.concurrent.{Executors, ThreadFactory}
|
||||
import java.util.concurrent.atomic.AtomicInteger
|
||||
import scala.concurrent.ExecutionContext
|
||||
import scala.concurrent.duration._
|
||||
import org.slf4j.LoggerFactory
|
||||
|
||||
abstract class BaseServerTest
|
||||
extends JsonRpcServerTestKit
|
||||
@ -235,7 +236,7 @@ abstract class BaseServerTest
|
||||
FileManager.props(
|
||||
config.fileManager,
|
||||
contentRootManagerWrapper,
|
||||
new FileSystem,
|
||||
new FileSystem(LoggerFactory.getLogger(classOf[BaseServerTest])),
|
||||
zioExec
|
||||
),
|
||||
s"file-manager-${UUID.randomUUID()}"
|
||||
@ -273,7 +274,7 @@ abstract class BaseServerTest
|
||||
config,
|
||||
contentRootManagerWrapper,
|
||||
watcherFactory,
|
||||
new FileSystem,
|
||||
new FileSystem(LoggerFactory.getLogger(classOf[BaseServerTest])),
|
||||
zioExec
|
||||
),
|
||||
s"fileevent-registry-${UUID.randomUUID()}"
|
||||
|
Loading…
Reference in New Issue
Block a user