Skip to content

Fix too many open files issue #1443

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
rondinelisaad wants to merge 1 commit into
base: main
Choose a base branch
from
+66 −30
Open

Fix too many open files issue #1443

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
96 changes: 66 additions & 30 deletions core/utils/profiling_tools.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,42 @@
profiling_logger.warning(f"PROFILING_LOG_HIGH_MEMORY={PROFILING_LOG_HIGH_MEMORY}")


def _get_memory_usage_mb(process=None):
"""
Returns the current RSS in MB when psutil can read it.
Profiling must never break application requests, especially when the
container is already under file descriptor pressure.
"""
try:
if process is None:
process = psutil.Process()
return process.memory_info().rss / 1024 / 1024
except (OSError, psutil.Error) as exc:
profiling_logger.debug("Skipping profiling memory sample: %s", exc)
return None


def _get_memory_delta_mb(process, start_memory):
if start_memory is None:
return None

end_memory = _get_memory_usage_mb(process)
if end_memory is None:
return None

return end_memory - start_memory


def _format_memory_delta(memory_used):
if memory_used is None:
return "unavailable"
return f"+{memory_used:.1f}MB"


def _is_high_memory(memory_used):
return memory_used is not None and memory_used > PROFILING_LOG_HIGH_MEMORY


def profile_endpoint(func):
"""
Decorador minimalista para profiling
Expand All @@ -36,7 +72,7 @@ def wrapper(self, request, *args, **kwargs):
# Dados iniciais
process = psutil.Process()
start_time = time.time()
start_memory = process.memory_info().rss / 1024 / 1024 # MB
start_memory = _get_memory_usage_mb(process)
start_queries = len(connection.queries)

try:
Expand All @@ -45,26 +81,25 @@ def wrapper(self, request, *args, **kwargs):

# Coleta métricas finais
end_time = time.time()
end_memory = process.memory_info().rss / 1024 / 1024
end_queries = len(connection.queries)

# Calcula diferenças
duration = end_time - start_time
memory_used = end_memory - start_memory
memory_used = _get_memory_delta_mb(process, start_memory)
queries_count = end_queries - start_queries

msg = (
f"request detected | "
f"endpoint: {request.path} | "
f"duration: {duration:.2f}s | "
f"memory: +{memory_used:.1f}MB | "
f"memory: {_format_memory_delta(memory_used)} | "
f"queries: {queries_count} | "
f"user: {getattr(request.user, 'username', 'anonymous')}"
)

# Log apenas se for relevante
if (duration > PROFILING_LOG_SLOW_REQUESTS) or (
memory_used > PROFILING_LOG_HIGH_MEMORY
if (duration > PROFILING_LOG_SLOW_REQUESTS) or _is_high_memory(
memory_used
):
profiling_logger.warning(f"Slow {msg}")
# Se muito lento, log das queries mais demoradas
Expand All @@ -87,7 +122,8 @@ def wrapper(self, request, *args, **kwargs):
response["X-Response-Time"] = f"{duration:.3f}"
if settings.DEBUG:
response["X-DB-Queries"] = str(queries_count)
response["X-Memory-Used"] = f"{memory_used:.1f}"
if memory_used is not None:
response["X-Memory-Used"] = f"{memory_used:.1f}"

return response

Expand Down Expand Up @@ -137,29 +173,29 @@ def wrapper(cls, *args, **kwargs):
# Profiling
process = psutil.Process()
start_time = time.time()
start_memory = process.memory_info().rss / 1024 / 1024
start_memory = _get_memory_usage_mb(process)
start_queries = len(connection.queries)

try:
result = func(cls, *args, **kwargs)

# Métricas
duration = time.time() - start_time
memory_used = process.memory_info().rss / 1024 / 1024 - start_memory
memory_used = _get_memory_delta_mb(process, start_memory)
queries_count = len(connection.queries) - start_queries

# Log
msg = (
f"classmethod | "
f"{method_info['class']}.{method_info['method']} | "
f"duration: {duration:.2f}s | "
f"memory: +{memory_used:.1f}MB | "
f"memory: {_format_memory_delta(memory_used)} | "
f"queries: {queries_count} | "
f"user: {method_info['user']} | "
f"file: {method_info['filename']}"
)
if (duration > PROFILING_LOG_SLOW_REQUESTS) or (
memory_used > PROFILING_LOG_HIGH_MEMORY
if (duration > PROFILING_LOG_SLOW_REQUESTS) or _is_high_memory(
memory_used
):
profiling_logger.warning(f"Slow {msg}")
elif PROFILING_LOG_ALL:
Expand Down Expand Up @@ -200,15 +236,15 @@ def wrapper(self, *args, **kwargs):
# Profiling
process = psutil.Process()
start_time = time.time()
start_memory = process.memory_info().rss / 1024 / 1024
start_memory = _get_memory_usage_mb(process)
start_queries = len(connection.queries)

try:
result = func(self, *args, **kwargs)

# Métricas
duration = time.time() - start_time
memory_used = process.memory_info().rss / 1024 / 1024 - start_memory
memory_used = _get_memory_delta_mb(process, start_memory)
queries_count = len(connection.queries) - start_queries

# Log
Expand All @@ -217,12 +253,12 @@ def wrapper(self, *args, **kwargs):
f"{method_info['class']}.{method_info['method']} | "
f"instance: {method_info['instance_id']} | "
f"duration: {duration:.2f}s | "
f"memory: +{memory_used:.1f}MB | "
f"memory: {_format_memory_delta(memory_used)} | "
f"queries: {queries_count}"
)

if (duration > PROFILING_LOG_SLOW_REQUESTS) or (
memory_used > PROFILING_LOG_HIGH_MEMORY
if (duration > PROFILING_LOG_SLOW_REQUESTS) or _is_high_memory(
memory_used
):
profiling_logger.warning(f"Slow {msg}")

Expand Down Expand Up @@ -426,15 +462,15 @@ def wrapper(*args, **kwargs):

process = psutil.Process()
start_time = time.time()
start_memory = process.memory_info().rss / 1024 / 1024
start_memory = _get_memory_usage_mb(process)
start_queries = len(connection.queries)

try:
result = func(*args, **kwargs)

# Métricas
duration = time.time() - start_time
memory_used = process.memory_info().rss / 1024 / 1024 - start_memory
memory_used = _get_memory_delta_mb(process, start_memory)
queries_count = len(connection.queries) - start_queries

# Informações adicionais sobre o resultado
Expand All @@ -453,7 +489,7 @@ def wrapper(*args, **kwargs):
f"{func_info['module']}.{func_info['function']} | "
f"args: {func_info['args_count']}, kwargs: {func_info['kwargs_count']} | "
f"duration: {duration:.2f}s | "
f"memory: +{memory_used:.1f}MB | "
f"memory: {_format_memory_delta(memory_used)} | "
f"queries: {queries_count}"
f"{result_info}"
)
Expand All @@ -464,8 +500,8 @@ def wrapper(*args, **kwargs):
" | args:", f" | first_arg: {func_info['first_arg']} | args:"
)

if (duration > PROFILING_LOG_SLOW_REQUESTS) or (
memory_used > PROFILING_LOG_HIGH_MEMORY
if (duration > PROFILING_LOG_SLOW_REQUESTS) or _is_high_memory(
memory_used
):
profiling_logger.warning(f"Slow {msg}")

Expand Down Expand Up @@ -521,26 +557,26 @@ def wrapper(*args, **kwargs):

process = psutil.Process()
start_time = time.time()
start_memory = process.memory_info().rss / 1024 / 1024
start_memory = _get_memory_usage_mb(process)
start_queries = len(connection.queries)

try:
result = func(*args, **kwargs)

duration = time.time() - start_time
memory_used = process.memory_info().rss / 1024 / 1024 - start_memory
memory_used = _get_memory_delta_mb(process, start_memory)
queries_count = len(connection.queries) - start_queries

msg = (
f"staticmethod | "
f"{method_info['module']}.{method_info['function']} | "
f"duration: {duration:.2f}s | "
f"memory: +{memory_used:.1f}MB | "
f"memory: {_format_memory_delta(memory_used)} | "
f"queries: {queries_count}"
)

if (duration > PROFILING_LOG_SLOW_REQUESTS) or (
memory_used > PROFILING_LOG_HIGH_MEMORY
if (duration > PROFILING_LOG_SLOW_REQUESTS) or _is_high_memory(
memory_used
):
profiling_logger.warning(f"Slow {msg}")
elif PROFILING_LOG_ALL:
Expand Down Expand Up @@ -581,18 +617,18 @@ def __call__(self, request):
return self.get_response(request)

start_time = time.time()
start_memory = self.process.memory_info().rss / 1024 / 1024
start_memory = _get_memory_usage_mb(self.process)

response = self.get_response(request)

duration = time.time() - start_time
memory_delta = self.process.memory_info().rss / 1024 / 1024 - start_memory
memory_delta = _get_memory_delta_mb(self.process, start_memory)

# Log apenas requisições problemáticas
if duration > PROFILING_LOG_SLOW_REQUESTS:
profiling_logger.warning(
f"Slow: {request.method} {request.path} - "
f"{duration:.2f}s - {memory_delta:+.1f}MB"
f"{duration:.2f}s - {_format_memory_delta(memory_delta)}"
)

return response
Expand Down
Loading