|
A logger can be used to demonstrate the behavior of Django asynchronous signals. By examining logged messages, the sequence in which synchronous and asynchronous signal handlers are executed, as well as the time taken for each execution, can be compared. This helps demonstrate blocking and non-blocking operations by comparing their sequence and time of execution.
In this guide, both synchronous and asynchronous signals for profile creation and image resizing will be tested to show the differences between blocking (synchronous) and non-blocking (asynchronous) operations.
Why Use Asynchronous SignalsA developer might have concerns and questions on why opt for Asynchronous signals when synchronous signals are simple, work with fewer codes, and require fewer dependencies. But think of the Django application as a project management system, where a project manager personally handles every task sequentially instead of redirecting tasks to different team members, in this scenario, the project manager must complete one task before starting another. For example, for a task that involves gathering and analyzing data, the manager must wait till all the data is collected before analyses, while the manager is engaged in one task, the other task is put on hold or `BLOCKED` leading to a delay in execution time, inefficiency, reduced responsiveness, scalability issues, and time wastage. If the manager fails at one point, there is a possible failure of the entire workflow.
But if the manager assigns the task to different team members based on their expertise, the tasks are carried out simultaneously, example one team member collects the data while another analyses the data simultaneously, the progress can be monitored by the manager and any related issues are addressed without stopping the whole workflow, this is an example of `NON-BLOCKING` operations and it improves overall project performance and efficiency.
Non-blocking I/O (input/output) operations are processes that do not prevent a program from executing other tasks while waiting for the I/O operation to complete. Asynchronous signals allow signal handlers to be async functions which are useful in performing non-blocking I/O(input/output) operations as in the case, example a database or network queries.
Customizing Logger for Synchronous SignalsTo effectively capture the sequence of events and elapsed time between each event such as creating a user, creating a user profile instance, and resizing the image before saving it in the database, a customized logger will be implemented. This logger will print these messages to ease thorough testing of synchronous signals.
Python
#settings.py
import logging
#class CustomFormatter(logging.Formatter):
def format(self, record):
if not hasattr(record, 'elapsed'):
record.elapsed = 0.0 # Provide a default value for 'elapsed'
return super().format(record)
# Update the logging configuration
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'handlers': {
'console': {
'level': 'DEBUG',
'class': 'logging.StreamHandler',
'formatter': 'verbose',
},
},
'formatters': {
'verbose': {
'()': CustomFormatter,
'format': '{asctime} {levelname} {name}:{lineno} [{elapsed:.3f}s] - {message}',
'style': '{',
},
},
'loggers': {
'django': {
'handlers': ['console'],
'level': 'INFO',
'propagate': True,
},
'django.server': { # Suppress django.server logs
'handlers': ['console'],
'level': 'ERROR', # Only show errors and above
'propagate': False,
},
'user': {
'handlers': ['console'],
'level': 'DEBUG',
'propagate': False,
},
'PIL': { # Reduce verbosity for PIL library
'handlers': ['console'],
'level': 'ERROR',
'propagate': False,
},
},
'root': {
'handlers': ['console'],
'level': 'WARNING', # Default root level to WARNING
},
}
Creating and Testing Synchronous SignalFirst, write synchronous signals to create a Profile instance for a newly created User instance and resize the image before saving it to the database.
Creating a FormCreate a form class in `forms.py` to handle user registration, including fields for username, password, email, and image.
Python
#models.py
from django import forms
from django.contrib.auth.models import User
class UserRegistrationForm(forms.Form):
username = forms.CharField(max_length=150)
email = forms.EmailField()
password = forms.CharField(widget=forms.PasswordInput)
image = forms.ImageField()
def clean_username(self):
username = self.cleaned_data['username']
if User.objects.filter(username=username).exists():
raise forms.ValidationError("Username is already taken.")
return username
def clean_email(self):
email = self.cleaned_data['email']
if User.objects.filter(email=email).exists():
raise forms.ValidationError("Email is already registered.")
return email
return user
Creating a View to Handle User RegistrationThe view submits the registration form after validating user credentials, creates a user, instantiates the profile model with the uploaded image, and logs messages at every point during execution with the timestamp.
Python
#views.py
import logging
import time
from datetime import datetime
from django.shortcuts import render, redirect
from django.contrib.auth.models import User
from .forms import UserRegistrationForm
logger = logging.getLogger(__name__)
def register(request):
if request.method == 'POST':
form = UserRegistrationForm(request.POST, request.FILES)
if form.is_valid():
username = form.cleaned_data['username']
email = form.cleaned_data['email']
password = form.cleaned_data['password']
image = form.cleaned_data['image']
start_time = time.time()
logger.info(f"{datetime.now().strftime('%H:%M:%S')} - Starting user creation process")
# Create the user
user = User.objects.create_user(username=username, email=email, password=password)
elapsed_time_user_creation = time.time() - start_time
logger.info(f"{datetime.now().strftime('%H:%M:%S')} - \
User created: {username} ({email}) in {elapsed_time_user_creation:.3f} seconds",
extra={'elapsed': elapsed_time_user_creation})
# Create or update the profile with the image
if image:
start_time_profile = time.time()
user.profile.image = image
user.profile.save()
elapsed_time_profile_update = time.time() - start_time_profile
logger.info(f"{datetime.now().strftime('%H:%M:%S')} -\
Profile updated for user: {username} in {elapsed_time_profile_update:.3f} seconds",
extra={'elapsed': elapsed_time_profile_update})
else:
logger.warning(f"{datetime.now().strftime('%H:%M:%S')} - \
No image provided for user: {username}")
logger.info(f"{datetime.now().strftime('%H:%M:%S')} -\
Redirecting to login page after successful registration: {username}")
return redirect('login')
else:
form = UserRegistrationForm()
return render(request, 'register.html', {'form': form})
URL ConfigurationImport views from `.views` and map them to `urlpatterns` in `urls.py`, assuming both files are in the same app directory. Use a dot ( . ) to indicate the current directory.
Python
from django.urls import path
from . import views
url_pattern = [
path('register/', views.register, name='register'),
Creating a User Profile ModelCreate a profile model for the user with a `OneToOneField` linking it directly to the User model. This relationship ensures that each instance of the User model is associated with only one instance of the Profile model. Include fields such as image and bio in the Profile model, with pre-populated default values for newly registered user profiles.
Python
#models.py
from django.db import models
from django.contrib.auth.models import User
from PIL import Image
class Profile(models.Model):
user = models.OneToOneField(User, on_delete=models.CASCADE)
image = models.ImageField(upload_to='profile_pics/', null=True)
bio = models.TextField(blank=True, default= 'This is a default bio')
location = models.CharField(max_length=100, blank=True)
def __str__(self):
return f"{self.user.username}'s Profile"
Creating Functions to Handle SignalsImport post_save from `django.db.models.signals` to detect when a new user is saved in the database. Import the@receiver decorator from `django.dispatch` to connect the signal to the `create_profilesignal` handler using the `receiver` decorator’s connect() method. The `create_profile` signal handler checks if a new user is created and then creates a corresponding profile instance for that user. The `save_profile` signal handler performs a similar task to save the user’s associated profile.
Python
#signals.py
from django.db.models.signals import post_save
from django.contrib.auth.models import User
from django.dispatch import receiver
from .models import Profile
from PIL import Image
import time
import logging
logger = logging.getLogger(__name__)
@receiver(post_save, sender=User)
def create_profile(sender, instance, created, **kwargs):
if created:
start_time = time.time()
Profile.objects.create(user=instance)
elapsed_time = time.time() - start_time
logger.info(f"Created Profile for user: \
{instance.username} in {elapsed_time:.3f} seconds",
extra={'elapsed': elapsed_time})
@receiver(post_save, sender=Profile)
def resize_profile_image(sender, instance, **kwargs):
if instance.image:
start_time = time.time()
time.sleep(5)
logger.info(f"Image processing started for user: {instance.user.username}")
img = Image.open(instance.image.path)
if img.height > 300 or img.width > 300:
output_size = (300, 300)
img.thumbnail(output_size)
img.save(instance.image.path)
elapsed_time = time.time() - start_time
logger.info(f"Image processing complete for user: \
{instance.user.username} in {elapsed_time:.3f} seconds",
extra={'elapsed': elapsed_time})
Connecting Signals to AppImporting signals in your `app.py` allows signal handlers to be connected to signals when the application is initialized.
Python
from django.apps import AppConfig
class UserConfig(AppConfig):
default_auto_field = 'django.db.models.BigAutoField'
name = 'user'
def ready(self):
import user.signals
Creating a userWhen the registration form is submitted and a new user is created, the `create_profile_signal` is triggered to create a new profile. The `resize_profile_image` signal is also triggered to resize the uploaded image and update the profile with the resized image. A sleep timer is set to simulate processing time for a large image file uploaded with the form, which takes 5 seconds to process.
If your logger is correctly configured, you should see the event sequence with timestamps as follows:
2024-06-25 10:30:54,558 INFO user.signals:56 [0.112s] – Created Profile for user: testuser in 0.112 seconds
2024-06-25 10:30:54,562 INFO user.views:82 [1.386s] – User created: testuser ([email protected]) in 1.386 seconds
2024-06-25 10:30:59,683 INFO user.signals:63 [0.000s] – Image processing started for user: testuser
2024-06-25 10:30:59,749 INFO user.signals:72 [5.066s] – Image processing complete for user: testuser in 5.066 seconds
2024-06-25 10:30:59,749 INFO user.views:90 [5.185s] – Profile updated for user: testuser in 5.185 seconds
Based on the logger information above, it is observed that resizing the image takes approximately 5.066 seconds. As a synchronous operation, the registration view waits for this task to complete before updating the profile and redirecting to the login page. This highlights a disadvantage of synchronous signals in web applications. In the next section, we will convert these signals to asynchronous signals.
Setting up Asynchronous Signals with Huey and SQLite BrokerTo implement async signals, you need a background task manager and a message broker for handling messages.
In this tutorial, we’ll use Huey and an SQLite broker due to their lightweight nature, easy setup, simplicity, and seamless integration with Django applications.
Installing Huey with pip:
pip install huey Customizing Huey in setting.py to use SQLite as its messaging broker.
Python
#settings.py
from huey import SqliteHuey
HUEY = {
'huey_class': 'huey.SqliteHuey', # Use the SqliteHuey class
'name': 'user-huey-app', # Change to desired name
'results': True, # Enable result storage
'store_none': False, # If a task returns None, do not save
'immediate': False, # If DEBUG=True, run synchronously
'utc': True,
'filename': 'huey.sqlite3', #
}
Creating TasksIn the app directory, create a file named `huey_tasks.py` and define a task for resizing the image. Tasks, as the name implies, are functions executed asynchronously in the background. They are used to offload time-consuming operations, such as image resizing, to ensure they do not block the main thread regardless of their duration. Importing models inside functions, like in `resize_profile_image_task`, ensures Django apps are fully ready to avoid the `AppRegistryNotReady error`.
Python
#huey_tasks.py
from huey.contrib.djhuey import task
from PIL import Image
from django.conf import settings
import os
import logging
import time
from datetime import datetime
logger = logging.getLogger(__name__)
huey_logger = logging.getLogger('huey')
@task()
def resize_profile_image_task(profile_id):
try:
from .models import Profile
start_time = time.time()
logger.info(f"{datetime.now().strftime('%H:%M:%S')} - \
Starting image processing for profile ID: {profile_id}")
time.sleep(5)
instance = Profile.objects.get(id=profile_id)
if instance.image:
img_path = os.path.join(settings.MEDIA_ROOT, str(instance.image))
img = Image.open(img_path)
if img.height > 300 or img.width > 300:
output_size = (300, 300)
img.thumbnail(output_size)
img.save(img_path)
elapsed_time = time.time() - start_time
logger.info(f"{datetime.now().strftime('%H:%M:%S')} - \
Image processing complete for user: \
{instance.user.username} in {elapsed_time:.3f} seconds",
extra={'elapsed': elapsed_time})
huey_logger.info(f"{datetime.now().strftime('%H:%M:%S')} - \
Image processing complete for user: \
{instance.user.username} in {elapsed_time:.3f} seconds",
extra={'elapsed': elapsed_time})
else:
logger.warning(f"{datetime.now().strftime('%H:%M:%S')} - \
No image found for user: {instance.user.username}")
except Profile.DoesNotExist:
logger.error(f"{datetime.now().strftime('%H:%M:%S')} -\
Profile with id {profile_id} does not exist.")
In the app directory, create a file named `huey_tasks.py` and define a task for resizing images. Tasks, as the name implies, are functions executed asynchronously in the background. They are designed to offload time-consuming operations such as image resizing to ensure they do not block the main thread regardless of their duration.
Linking Task to signals
Python
#signals.py
import logging
import time
from django.db.models.signals import post_save
from django.contrib.auth.models import User
from django.dispatch import receiver
from .models import Profile
from .huey_tasks import resize_profile_image_task
logger = logging.getLogger(__name__)
@receiver(post_save, sender=User)
def create_profile(sender, instance, created, **kwargs):
if created:
start_time = time.time()
profile = Profile.objects.create(user=instance)
elapsed_time = time.time() - start_time
logger.info(f"Created Profile for user: {instance.username} in {elapsed_time:.3f} seconds",
extra={'elapsed': elapsed_time})
@receiver(post_save, sender=Profile)
def resize_image(sender, instance, created, **kwargs):
if created:
start_time = time.time()
resize_profile_image_task(profile_id=instance.id)
elapsed_time = time.time() - start_time
logger.info(f"Image resized for profile: {instance.id} in {elapsed_time:.3f} seconds",
extra={'elapsed': elapsed_time})
When a user profile is created, the post_save signal of the profile model triggers the `resize_image signal` handler, which then triggers the `resize_profile_image_task`. This ensures that the image is resized without blocking other operations before the profile data is fully saved to the database.
Testing Async SignalsTo start the Huey consumer process run the below command in the same directory as manage.py.
run py manage.py run_huey This command executes tasks queued by Huey, facilitating background task processing within your application. Successful execution should resemble the CMD output below:
(env) C:\Users\Admin\Desktop\newproject\myproject>py manage.py run_huey
[2024-06-25 13:25:34,539] INFO:huey.consumer:MainThread:Huey consumer started with 1 thread, PID 4684 at 2024-06-25 20:25:34.539063
2024-06-25 13:25:34,539 INFO huey.consumer:389 [0.000s] – Huey consumer started with 1 thread, PID 4684 at 2024-06-25 20:25:34.539063
[2024-06-25 13:25:34,539] INFO:huey.consumer:MainThread:Scheduler runs every 1 second(s).
2024-06-25 13:25:34,539 INFO huey.consumer:392 [0.000s] – Scheduler runs every 1 second(s).
[2024-06-25 13:25:34,540] INFO:huey.consumer:MainThread:Periodic tasks are enabled.
2024-06-25 13:25:34,540 INFO huey.consumer:394 [0.000s] – Periodic tasks are enabled.
[2024-06-25 13:25:34,540] INFO:huey.consumer:MainThread:The following commands are available:
+ user.huey_tasks.resize_profile_image_task
2024-06-25 13:25:34,540 INFO huey.consumer:401 [0.000s] – The following commands are available:
+ user.huey_tasks.resize_profile_image_task
The output confirms that Huey, the task queue manager, has started with one processing thread and it’s ready to execute the task `user.huey_tasks.resize_profile_image_task`. Replace (env) C:\\Users\\Admin\\Desktop\\newproject\\myproject>py manage.py run_huey command to the actual directory in your project.
Proceed to register a new user and on successful registration and redirection to the login page, observe the sequence of tasks processed along with their timestamps displayed in your terminal, as shown below.
System check identified no issues (0 silenced).
June 25, 2024 – 13:18:51
Django version 5.0.6, using settings ‘myproject.settings’
Starting development server at http://127.0.0.1:8000/
Quit the server with CTRL-BREAK.
2024-06-25 13:20:06,329 INFO user.views:75 [0.000s] – 13:20:06 – Starting user creation process
2024-06-25 13:20:07,488 INFO user.signals:106 [0.000s] – 13:20:07 – Starting profile creation for user: testuser
2024-06-25 13:20:07,635 INFO user.signals:116 [0.000s] – 13:20:07 – Starting image resizing for profile ID: 53
2024-06-25 13:20:07,641 INFO user.signals:121 [0.007s] – 13:20:07 – Image resize task triggered for profile: 53 in 0.007 seconds
2024-06-25 13:20:07,642 INFO user.signals:110 [0.155s] – 13:20:07 – Created Profile for user: testuser in 0.155 seconds
2024-06-25 13:20:07,644 INFO user.views:80 [1.315s] – 13:20:07 – User created: testuser ([email protected]) in 1.315 seconds
2024-06-25 13:20:07,777 INFO user.views:88 [0.131s] – 13:20:07 – Profile updated for user: testuser in 0.131 seconds
2024-06-25 13:20:07,777 INFO user.views:92 [0.000s] – 13:20:07 – Redirecting to login page after successful registration: testuser
The `image_profile_image_resize_task` function includes a 5-second delay to show how the asynchronous signal handles tasks in the background without slowing down other processes or threads. while the offloaded image resizes task was completed in the background after waiting for 5 seconds, as seen in the Huey log messages below.
(env) C:\Users\Admin\Desktop\newproject\myproject>py manage.py run_huey
2024-06-25 13:19:36,444 INFO huey.consumer: Huey consumer started with 1 thread, PID 10132
2024-06-25 13:19:36,445 INFO huey.consumer: Scheduler runs every 1 second(s)
2024-06-25 13:19:36,446 INFO huey.consumer: Periodic tasks are enabled
2024-06-25 13:19:36,446 INFO huey.consumer: Available commands: user.huey_tasks.resize_profile_image_task
2024-06-25 13:20:09,192 INFO huey: Executing user.huey_tasks.resize_profile_image_task: 9f9a8f5d-fe85-4f5b-b9ca-2c8e742c5ce0
2024-06-25 13:20:09,193 INFO user.huey_tasks: 13:20:09 – Starting image processing for profile ID: 53
2024-06-25 13:20:14,271 INFO user.huey_tasks: 13:20:14 – Image processing complete for user: testuser in 5.077 seconds
2024-06-25 13:20:14,273 INFO huey: user.huey_tasks.resize_profile_image_task executed in 5.079 seconds
The Huey consumer started and scheduled the `resize_profile_image_task`. While the main thread managed to create the user and profile updates in just over a second, the image resizing for profile ID 53 was offloaded at 13:20:07. Running in the background, this task was completed at 13:20:14, taking around 5 seconds. This setup keeps the app responsive, letting user operations finish fast without getting slowed down by the image resizing process.
Output:
Best Practices- Start by making sure your SQLite broker is correctly set up with Huey in your Django project. This means configuring everything so that your tasks can run smoothly and connect properly.
- When designing your tasks, like image resizing, make sure they run in the background by regularly checking the Huey command log messages to confirm that tasks are being registered and processed correctly.
- Carefully use Django signals to trigger asynchronous tasks, separating heavy processing tasks like image resizing from the main application thread and offloading them to Huey. Ensure to include comprehensive error handling, retry logic, and logging at each step to monitor for errors. This helps in debugging and testing task flows in both development and production environments, ensuring responsive user interactions.
|
