title: Multiple Postgres SELECT processes(django GET requests) stuck, causing 100% CPU usage
body: <p>I'll try to give as much information I can here. Although the solution would be great, I just want guidance on how to tackle the problem. How to view more useful log files, etc. As I'm new to server maintainance. Any advice are welcome.</p>
  
  <p>Here's what's happenning in chronological order:</p>
  
  <ul>
  <li>I'm running 2 digitalocean droplets (Ubuntu 14.04 VPS)</li>
  <li>Droplet #1 running django, nginx, gunicorn</li>
  <li>Droplet #2 running postgres</li>
  <li>Everything runs fine for a month and suddenly the postgres droplet
  CPU usage spiked to 100%</li>
  <li>You can see htop log when this happens. I've attached a screenshot</li>
  <li>Another screenshot is nginx error.log, you can see that problem
  started at 15:56:14 where I highlighted with red box</li>
  <li>sudo poweroff the Postgres droplet and restart it doesn't fix the
  problem</li>
  <li>Restore postgres droplet to my last backup (20 hours ago) solves the problem but it keep happening again. This is 7th time in 2 days</li>
  </ul>
  
  <p>I'll continue to do research and give more information. Meanwhile any opinions are welcome.</p>
  
  <p>Thank you.</p>
  
  <p><a href="https://i.stack.imgur.com/mm80Q.jpg" rel="nofollow noreferrer"><img src="https://i.stack.imgur.com/mm80Q.jpg" alt="Postgres server htop log when problem occurs"></a>
  <a href="https://i.stack.imgur.com/uyKer.jpg" rel="nofollow noreferrer"><img src="https://i.stack.imgur.com/uyKer.jpg" alt="nginx error.log when problem occurs"></a></p>
  
  <p><strong>Update 20 May 2016</strong></p>
  
  <ul>
  <li>Enabled slow query logging on Postgres server as recommended by <em>e4c5</em></li>
  <li>6 hours later, server freezed(100% CPU usage) again at 8:07 AM. I've attached all related screenshots</li>
  <li>Browser display 502 error if try to access the site during the freeze</li>
  <li><code>sudo service restart postgresql</code> (and gunicorn, nginx on django server) does <strong>NOT</strong> fix
  the freeze (<strong>I think this is a very interesting point</strong>)</li>
  <li>However, restore Postgres server to my previous backup(now 2 days old) <strong>does</strong> fix the freeze</li>
  <li>The culprit <strong>Postgres log</strong> message is <strong>Could not send data to client: Broken
  Pipe</strong></li>
  <li>The culprit <strong>Nginx log</strong> message is a simple django-rest-framework<br>
  api call which return only 20 items (each with some foreign-key data
  query)</li>
  </ul>
  
  <p><strong>Update#2 20 May 2016</strong> 
  When the freeze occurs, I tried doing the following in chronological order (turn off everything and turn them back on one-by-one)</p>
  
  <ul>
  <li><code>sudo service stop postgresql</code> --> cpu usage fall to 0-10%</li>
  <li><code>sudo service stop gunicorn</code> --> cpu usage stays at 0-10%</li>
  <li><code>sudo service stop nginx</code>--> cpu usage stays at to 0-10%</li>
  <li><code>sudo service restart postgresql</code> --> cpu usage stays at to 0-10%</li>
  <li><code>sudo service restart gunicorn</code> --> cpu usage stays at to 0-10%</li>
  <li><code>sudo service restart nginx</code> --> <strong>cpu usage rose to 100% and stays
  there</strong></li>
  </ul>
  
  <p>So this is not about server load or long query time then? </p>
  
  <p>This is very confusing since if I restore database to my latest backup (2 days ago), everything is back online even without touching nginx/gunicorn/django server...</p>
  
  <hr>
  
  <p>Update 8 June 2016
  I turned on slow query logging. Set it to log queries that takes longer than 1000ms.</p>
  
  <p>I got this one query shows up in the log many times.</p>
  
  <pre><code>SELECT
       "products_product"."id",
       "products_product"."seller_id",
       "products_product"."priority",
       "products_product"."media",
       "products_product"."active",
       "products_product"."title",
       "products_product"."slug",
       "products_product"."description",
       "products_product"."price",
       "products_product"."sale_active",
       "products_product"."sale_price",
       "products_product"."timestamp",
       "products_product"."updated",
       "products_product"."draft",
       "products_product"."hitcount",
       "products_product"."finished",
       "products_product"."is_marang_offline",
       "products_product"."is_seller_beta_program",
       COUNT("products_video"."id") AS "num_video"
   FROM "products_product"
   LEFT OUTER JOIN "products_video" ON ( "products_product"."id" = "products_video"."product_id" )
   WHERE ("products_product"."draft" = false AND "products_product"."finished" = true)
   GROUP BY
       "products_product"."id",
       "products_product"."seller_id",
       "products_product"."priority",
       "products_product"."media",
       "products_product"."active",
       "products_product"."title",
       "products_product"."slug",
       "products_product"."description",
       "products_product"."price",
       "products_product"."sale_active",
       "products_product"."sale_price",
       "products_product"."timestamp",
       "products_product"."updated",
       "products_product"."draft",
       "products_product"."hitcount",
       "products_product"."finished",
       "products_product"."is_marang_offline",
       "products_product"."is_seller_beta_program"
   HAVING COUNT("products_video"."id") &gt;= 8
   ORDER BY "products_product"."priority" DESC, "products_product"."hitcount" DESC
   LIMIT 100
  </code></pre>
  
  <p>I know it's such an ugly query (generated by django aggregation). In English, this query just means <strong><em>"give me a list of products that have more than 8 videos in it".</em></strong> </p>
  
  <p>And here the EXPLAIN output of this query:</p>
  
  <pre><code>                  QUERY PLAN                                                                                                                                                                                                                 
  ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
   Limit  (cost=351.90..358.40 rows=100 width=933)
     -&gt;  GroupAggregate  (cost=351.90..364.06 rows=187 width=933)
           Filter: (count(products_video.id) &gt;= 8)
           -&gt;  Sort  (cost=351.90..352.37 rows=187 width=933)
                 Sort Key: products_product.priority, products_product.hitcount, products_product.id, products_product.seller_id, products_product.media, products_product.active, products_product.title, products_product.slug, products_product.description, products_product.price, products_product.sale_active, products_product.sale_price, products_product."timestamp", products_product.updated, products_product.draft, products_product.finished, products_product.is_marang_offline, products_product.is_seller_beta_program
                 -&gt;  Hash Right Join  (cost=88.79..344.84 rows=187 width=933)
                       Hash Cond: (products_video.product_id = products_product.id)
                       -&gt;  Seq Scan on products_video  (cost=0.00..245.41 rows=2341 width=8)
                       -&gt;  Hash  (cost=88.26..88.26 rows=42 width=929)
                             -&gt;  Seq Scan on products_product  (cost=0.00..88.26 rows=42 width=929)
                                   Filter: ((NOT draft) AND finished)
  </code></pre>
  
  <h2>    (11 rows)</h2>
  
  <p><strong>--- Update 8 June 2016 #2 ---</strong>
  Since there are many suggestions by many people. So I'll try to apply the fixes one-by-one and report back periodically.</p>
  
  <p>@e4c5
  Here's the information you need:</p>
  
  <p>You can think of my site somewhat like Udemy, an online course marketplace. There are "Product"(course). Each product contain a number of videos. Users can comment on both Product page itself and each Videos.</p>
  
  <p>In many cases, I'll need to query a list of products order by number of TOTAL comments it got(the sum of product comments AND comments on each Video of that Product)</p>
  
  <p>The django query that correspond to the EXPLAIN output above:</p>
  
  <pre><code>all_products_exclude_draft = Product.objects.all().filter(draft=False)
  products_that_contain_more_than_8_videos =  all_products_exclude_draft.annotate(num_video=Count('video')).filter(finished=True, num_video__gte=8).order_by('timestamp')[:30]
  </code></pre>
  
  <p>I just noticed that I(or some other dev in my team) hit database twice with these 2 python lines.</p>
  
  <p>Here's the django models for Product and Video:</p>
  
  <pre><code>from django_model_changes import ChangesMixin
  
  class Product(ChangesMixin, models.Model):
      class Meta:
          ordering = ['-priority', '-hitcount']
      seller = models.ForeignKey(SellerAccount)
      priority = models.PositiveSmallIntegerField(default=1)
      media = models.ImageField(blank=True, 
              null=True, 
              upload_to=download_media_location,
              default=settings.MEDIA_ROOT + '/images/default_icon.png',
              storage=FileSystemStorage(location=settings.MEDIA_ROOT))
      active = models.BooleanField(default=True)
      title = models.CharField(max_length=500)
      slug = models.SlugField(max_length=200, blank=True, unique=True)
      description = models.TextField()
      product_coin_price = models.IntegerField(default=0)
      sale_active = models.BooleanField(default=False)
      sale_price = models.IntegerField(default=0, null=True, blank=True) #100.00
      timestamp = models.DateTimeField(auto_now_add=True, auto_now=False, null=True)
      updated = models.DateTimeField(auto_now_add=False, auto_now=True, null=True)
      draft = models.BooleanField(default=True)
      hitcount = models.IntegerField(default=0)
      finished = models.BooleanField(default=False)
      is_marang_offline = models.BooleanField(default=False)
      is_seller_beta_program = models.BooleanField(default=False)
  
      def __unicode__(self):
          return self.title
  
      def get_avg_rating(self):
          rating_avg = self.productrating_set.aggregate(Avg("rating"), Count("rating"))
          return rating_avg
  
      def get_total_comment_count(self):
          comment_count = self.video_set.aggregate(Count("comment"))
          comment_count['comment__count'] += self.comment_set.count()
          return comment_count
  
      def get_total_hitcount(self):
          amount = self.hitcount
          for video in self.video_set.all():
              amount += video.hitcount
          return amount
  
      def get_absolute_url(self):
          view_name = "products:detail_slug"
          return reverse(view_name, kwargs={"slug": self.slug})
  
      def get_product_share_link(self):
          full_url = "%s%s" %(settings.FULL_DOMAIN_NAME, self.get_absolute_url())
          return full_url
  
      def get_edit_url(self):
          view_name = "sellers:product_edit"
          return reverse(view_name, kwargs={"pk": self.id})
  
      def get_video_list_url(self):
          view_name = "sellers:video_list"
          return reverse(view_name, kwargs={"pk": self.id})
  
      def get_product_delete_url(self):
          view_name = "products:product_delete"
          return reverse(view_name, kwargs={"pk": self.id})
  
      @property
      def get_price(self):
          if self.sale_price and self.sale_active:
              return self.sale_price
          return self.product_coin_price
  
      @property
      def video_count(self):
          videoCount = self.video_set.count()
          return videoCount
  
  class Video(models.Model):
      seller = models.ForeignKey(SellerAccount)
      title = models.CharField(max_length=500)
      slug = models.SlugField(max_length=200, null=True, blank=True)
      story = models.TextField(default=" ")
      chapter_number = models.PositiveSmallIntegerField(default=1)
      active = models.BooleanField(default=True)
      featured = models.BooleanField(default=False)
      product = models.ForeignKey(Product, null=True)
      timestamp = models.DateTimeField(auto_now_add=True, auto_now=False, null=True)
      updated = models.DateTimeField(auto_now_add=False, auto_now=True, null=True)
      draft = models.BooleanField(default=True)
      hitcount = models.IntegerField(default=0)
      objects = VideoManager()
  
      class Meta:
          unique_together = ('slug', 'product')
          ordering = ['chapter_number', 'timestamp']
  
      def __unicode__(self):
          return self.title
  
      def get_comment_count(self):
          comment_count = self.comment_set.all_jing_jing().count()
          return comment_count
  
      def get_create_chapter_url(self):
          return reverse("sellers:video_create", kwargs={"pk": self.id})
  
      def get_edit_url(self):
          view_name = "sellers:video_update"
          return reverse(view_name, kwargs={"pk": self.id})
  
      def get_video_delete_url(self):
          view_name = "products:video_delete"
          return reverse(view_name, kwargs={"pk": self.id})
  
      def get_absolute_url(self):
          try:
              return reverse("products:video_detail", kwargs={"product_slug": self.product.slug, "pk": self.id})
          except:
              return "/"
  
      def get_video_share_link(self):
          full_url = "%s%s" %(settings.FULL_DOMAIN_NAME, self.get_absolute_url())
          return full_url      
  
      def get_next_url(self):
          current_product = self.product
          videos = current_product.video_set.all().filter(chapter_number__gt=self.chapter_number)
          next_vid = None
          if len(videos) &gt;= 1:
              try:
                  next_vid = videos[0].get_absolute_url()
              except IndexError:
                  next_vid = None
          return next_vid
  
      def get_previous_url(self):
          current_product = self.product
          videos = current_product.video_set.all().filter(chapter_number__lt=self.chapter_number).reverse()
          next_vid = None
          if len(videos) &gt;= 1:
              try:
                  next_vid = videos[0].get_absolute_url()
              except IndexError:
                  next_vid = None
          return next_vid
  </code></pre>
  
  <p>And here is the index of the Product and Video table I got from the command:</p>
  
  <pre><code>my_database_name=# \di
  </code></pre>
  
  <p>Note: this is photoshopped and include some other models as well.
  <a href="https://i.stack.imgur.com/q83EG.jpg" rel="nofollow noreferrer"><img src="https://i.stack.imgur.com/q83EG.jpg" alt="Indexes of Product and Video models"></a></p>
  
  <hr>
  
  <p><strong>--- Update 8 June 2016 #3 ---</strong>
  @Jerzyk
  As you suspected. After I inspect all my code again, I found that I indeed did a 'slicing-in-memory': I tried to shuffle the first 10 results by doing this:</p>
  
  <pre><code>def get_queryset(self):
          all_product_list = Product.objects.all().filter(draft=False).annotate(
          num_video=Count(
                  Case(
                      When(
                          video__draft=False,
                          then=1,
                      )
                  )
              )
          ).order_by('-priority', '-num_video', '-hitcount')
          the_first_10_products = list(all_product_list[:10])
          the_11th_product_onwards = list(all_product_list[10:])
          random.shuffle(copy)
          finalList = the_first_10_products + the_11th_product_onwards
  </code></pre>
  
  <p>Note: in the code above I need to count number of Video that is not in draft status.</p>
  
  <p>So this will be one of the thing I need to fix as well. Thanks. >_&lt; </p>
  
  <hr>
  
  <p>--- Here are the related screenshots ---</p>
  
  <p><em>Postgres log when freezing occurs (log_min_duration = 500 milliseconds)</em>
  <a href="https://i.stack.imgur.com/EzdlP.jpg" rel="nofollow noreferrer"><img src="https://i.stack.imgur.com/EzdlP.jpg" alt="Postgres log 20 May 2016"></a></p>
  
  <p><em>Postgres log (contunued from the above screenshot)</em>
  <a href="https://i.stack.imgur.com/7IFqN.jpg" rel="nofollow noreferrer"><img src="https://i.stack.imgur.com/7IFqN.jpg" alt="Postgres log 20 May 2016 (page2)"></a></p>
  
  <p><em>Nginx error.log in the same time period</em>
  <a href="https://i.stack.imgur.com/KKeLa.jpg" rel="nofollow noreferrer"><img src="https://i.stack.imgur.com/KKeLa.jpg" alt="Nginx log 20 May 2016"></a></p>
  
  <p><em>DigitalOcean CPU usage graph just before freezing</em>
  <a href="https://i.stack.imgur.com/SwVs7.jpg" rel="nofollow noreferrer"><img src="https://i.stack.imgur.com/SwVs7.jpg" alt="DigitalOcean graph 20 May 2016 (1)"></a></p>
  
  <p><em>DigitalOcean CPU usage graph just after freezing</em>
  <a href="https://i.stack.imgur.com/K2gmV.jpg" rel="nofollow noreferrer"><img src="https://i.stack.imgur.com/K2gmV.jpg" alt="DigitalOcean graph 20 May 2016 (2)"></a></p>